LEDs on GW and nodes aren't working as expected
-
The LEDs, both om my GWs and on my nodes, aren't working as expected. I'm using ATmega328, RFM69W, MQTT Ethernet on the GW and an updated version from the development branch.
Making some traces in the code of MyLeds.cpp it looks like the variable "prevTime" isn't being updated correctly.
In the routine "ledsProcess()" the variable "prevTime" is expected to be udated when timeout occurs comparing it with hwMillis(); and prepare itself for the next timeout to update the LEDs. But the variable is getting out of track and the LEDs get stuck for moments or aren't flickering when they should.Making the following change solves it.
Change line: https://github.com/mysensors/MySensors/blob/development/core/MyLeds.cpp#L58prevTime += LED_PROCESS_INTERVAL_MS;to:
prevTime = hhMillis();Maybe @hek or @tbowmo could look into this and verify if' it's the preferred solution or perhaps propose a better one.
If you need some more detailed traces from my rig, pls. let me know.
-
Thanks for the hint.. I'll update development branch..
-
@jpaulin said:
the variable is getting out of track
What exactly do you mean by this?
The variable prevTime is declared static, so it will keep its value over multiple calls of ledsProcess().
Current implementation should lead to more exact timing than your suggestion when ledsProcess() is called irregularly.
On second thought, maybe your loop() runs very irregularly or blocks for a long time. The mysensors library is updated outside the loop() function, but blocking the loop() will block the library and (also) prevents led updates...
-
@Yveaux
the loop takes 1.3 seconds to complete in my sketch.
The following sensor times are measured, including sendings:DHT22.temp = 280 mS DHT22.Humidity = 60 mS Emonlib.h = 850 mS (AC power sensors) RFM69.RSSI = 60 mS RFM69.temp = 60 mSThen the node wait(); in the loop eg. 60 seconds to start all-over.
I'll add hopefully later today some of my traces to show different time stamps and variable values in the core modules and in the setup.
-
@jpaulin This means the MySensors library will stall for 1.3 seconds every run; you cannot expect the leds to update more frequently than once per 1.3 seconds. Incoming messages might very well get lost if rate is more than a few per second.
I'd advise you to place at least a couple of wait() calls inbetween the sensor readings of your loops. The emonlib call might be broken down into smaller calls; e.g. do the averaging & min/max calculations yourself, or insert a wait() call into the loop of the blocking emonlib call.
-
@Yveaux (I'm splitting it in various posts, due to size limits.)
Thanks for your tips to add some wait() to the loop(). I'll add it to my script.
Here are some traces showing the out of track behavior of the variable prevTime in the module MyLeds.cpp, and I guess it's independent for long or short loop() times.
First I have added in MyLeds.cpp a number of time stamps and printouts (marked with "trace" ) to capture details of the erroneous behavior:/** * The MySensors Arduino library handles the wireless radio link and protocol * between your home built sensors/actuators and HA controller of choice. * The sensors forms a self healing radio network with optional repeaters. Each * repeater and gateway builds a routing tables in EEPROM which keeps track of the * network topology allowing messages to be routed to nodes. * * Created by Henrik Ekblad <henrik.ekblad@mysensors.org> * Copyright (C) 2013-2015 Sensnology AB * Full contributor list: https://github.com/mysensors/Arduino/graphs/contributors * * Documentation: http://www.mysensors.org * Support Forum: http://forum.mysensors.org * * This program is free software; you can redistribute it and/or * modify it under the terms of the GNU General Public License * version 2 as published by the Free Software Foundatio */ #include "MyLeds.h" #define LED_ON_OFF_RATIO (4) // Power of 2 please #define LED_PROCESS_INTERVAL_MS (MY_DEFAULT_LED_BLINK_PERIOD/LED_ON_OFF_RATIO) // these variables don't need to be volatile, since we are not using interrupts static uint8_t countRx; static uint8_t countTx; static uint8_t countErr; static unsigned long prevTime = hwMillis() - LED_PROCESS_INTERVAL_MS; // Substract some, to make sure leds gets updated on first run. // static unsigned long prevTime; inline void ledsInit() { Serial.print(hwMillis()); //trace Serial.println(" init:MyLeds.cpp:ledsInit()"); //trace Serial.print("var:prevTime="); //trace Serial.println(prevTime); //trace Serial.print("preproc_const:LED_PROCESS_INTERVAL_MS="); //trace Serial.println(LED_PROCESS_INTERVAL_MS); //trace // initialize counters countRx = 0; countTx = 0; countErr = 0; // Setup led pins #if defined(MY_DEFAULT_RX_LED_PIN) pinMode(MY_DEFAULT_RX_LED_PIN, OUTPUT); #endif #if defined(MY_DEFAULT_TX_LED_PIN) pinMode(MY_DEFAULT_TX_LED_PIN, OUTPUT); #endif #if defined(MY_DEFAULT_ERR_LED_PIN) pinMode(MY_DEFAULT_ERR_LED_PIN, OUTPUT); #endif ledsProcess(); } void ledsProcess() { Serial.print(hwMillis()); //trace Serial.println(" init:MyLeds.cpp:ledsPRocess()"); //trace // Just return if it is not the time... if ((hwMillis() - prevTime) < LED_PROCESS_INTERVAL_MS) { return; } prevTime += LED_PROCESS_INTERVAL_MS; Serial.print("var:prevTime="); //trace Serial.println(prevTime); //trace uint8_t state; // For an On/Off ratio of 4, the pattern repeated will be [on, on, on, off] // until the counter becomes 0. #if defined(MY_DEFAULT_RX_LED_PIN state = (countRx & (LED_ON_OFF_RATIO-1)) ? LED_ON : LED_OFF; Serial.print("var:countRx="); //trace Serial.println(countRx); //trace Serial.print("var:state="); //trace Serial.println(state); //trace hwDigitalWrite(MY_DEFAULT_RX_LED_PIN, state); if (countRx) { --countRx; } #endif #if defined(MY_DEFAULT_TX_LED_PIN) state = (countTx & (LED_ON_OFF_RATIO-1)) ? LED_ON : LED_OFF; Serial.print("var:countTx="); //trace Serial.println(countTx); //trace Serial.print("var:state="); //trace Serial.println(state); //trace hwDigitalWrite(MY_DEFAULT_TX_LED_PIN, state); if (countTx) { --countTx; } #endif #if defined(MY_DEFAULT_ERR_LED_PIN) state = (countErr & (LED_ON_OFF_RATIO-1)) ? LED_ON : LED_OFF; Serial.print("var:countErr="); //trace Serial.println(countErr); //trace Serial.print("var:state="); //trace Serial.println(state); //trace hwDigitalWrite(MY_DEFAULT_ERR_LED_PIN, state); if (countErr) { --countErr; } #endif } void ledsBlinkRx(uint8_t cnt) { Serial.print(hwMillis()); //trace Serial.println(" init:MyLeds.cpp:ledsBlinkRx()"); //trace Serial.print("var:cnt="); //trace Serial.println(cnt); //trace Serial.print("var:init_sub:countRx="); //trace Serial.println(countRx); //trace if (!countRx) { countRx = cnt*LED_ON_OFF_RATIO; } Serial.print("var:end_sub:countRx="); //trace Serial.println(countRx); //trace } void ledsBlinkTx(uint8_t cnt) { Serial.print(hwMillis()); //trace Serial.println(" init:MyLeds.cpp:ledsBlinkTx()"); //trace Serial.print( "var:cnt="); //trace Serial.println(cnt); //trace Serial.print("var:init_sub:countTx="); //trace Serial.println(countTx); //trace if(!countTx) { countTx = cnt*LED_ON_OFF_RATIO; } Serial.print("var:end_sub:countTx="); //trace Serial.println(countTx); //trace } void ledsBlinkErr(uint8_t cnt) { Serial.print(hwMillis()); //trace Serial.println(" init:MyLeds.cpp:ledsBlinkErr()"); //trace Serial.print( "var:cnt="); //trace Serial.println(cnt); //trace Serial.print("var:init_sub:countErr="); //trace Serial.println(countErr); //trace if(!countErr) { countErr = cnt*LED_ON_OFF_RATIO; } Serial.print("var:end_sub:countErr="); //trace Serial.println(countErr); //trace }The script being used for the test:
/** * The MySensors Arduino library handles the wireless radio link and protocol * between your home built sensors/actuators and HA controller of choice. * The sensors forms a self healing radio network with optional repeaters. Each * repeater and gateway builds a routing tables in EEPROM which keeps track of the * network topology allowing messages to be routed to nodes. * * Created by Henrik Ekblad <henrik.ekblad@mysensors.org> * Copyright (C) 2013-2015 Sensnology AB * Full contributor list: https://github.com/mysensors/Arduino/graphs/contributors * * Documentation: http://www.mysensors.org * Support Forum: http://forum.mysensors.org * * This program is free software; you can redistribute it and/or * modify it under the terms of the GNU General Public License * version 2 as published by the Free Software Foundation. * ******************************* * * REVISION HISTORY * Version 1.0 - Henrik EKblad * * DESCRIPTION * This sketch provides an example how to implement a humidity/temperature * sensor using DHT11/DHT-22 * http://www.mysensors.org/build/humidity */ // Enable debug prints #define MY_DEBUG // Enable and select radio type attached //#define MY_RADIO_NRF24 #define MY_RADIO_RFM69 #define MY_RFM69_FREQUENCY RF69_433MHZ #define MY_NODE_ID 3 // Set blinking period #define MY_DEFAULT_LED_BLINK_PERIOD 300 // Flash leds on rx/tx/err // Uncomment to override default HW configurations #define MY_DEFAULT_ERR_LED_PIN 7 // Error led pin red #define MY_DEFAULT_RX_LED_PIN 6 // Receive led pin yellow #define MY_DEFAULT_TX_LED_PIN 4 // Transmit led pin green #define emonTxV3 // Emonlib.h Fixes Arduino voltage reference calculations to 3.3V. Gets more accurate #include <MySensors.h> #include <DHT.h> #include "EmonLib.h" // Include Emon Library OpenEnergyMon.org EnergyMonitor ct1,ct2,ct3; // Create instances unsigned long SLEEP_TIME = 60000; // Sleep time between reads (in milliseconds) #define CHILD_ID_POW1 6 #define CHILD_ID_POW2 7 #define CHILD_ID_POW3 8 #define MEASURED_VOLTAGE 127.0 // Use fixed AC Voltage for the moment #define CHILD_ID_HUM 0 #define CHILD_ID_TEMP 1 #define DHTPIN 8 // Input pin from DHT22 #define DHTTYPE DHT22 DHT dht(DHTPIN, DHTTYPE); #define CHILD_ID_RSSI 4 #define CHILD_ID_TEMP2 5 int rssi; // RSSI measured on RFM69 chip int temp2; // Internal temperature on RFM69 chip MyMessage msgHum(CHILD_ID_HUM, V_HUM); MyMessage msgTemp(CHILD_ID_TEMP, V_TEMP); MyMessage msgPower1(CHILD_ID_POW1, V_WATT); MyMessage msgPower2(CHILD_ID_POW2, V_WATT); MyMessage msgPower3(CHILD_ID_POW3, V_WATT); MyMessage msgRSSI(CHILD_ID_RSSI, V_VAR1); MyMessage msgTemp2(CHILD_ID_TEMP2, V_TEMP); void setup() { dht.begin(); // Start-up DHT22 sensor Temperature/Humidity ct1.voltage(0, 234.26, 1.7); // Voltage: input pin, calibration, phase_shift ct2.voltage(0, 234.26, 1.7); ct3.voltage(0, 234.26, 1.7); ct1.current(1, 111.1); // Current: input pin, calibration. ct2.current(2, 111.1); ct3.current(3, 111.1); } void presentation() { // Send the sketch version information to the gateway and Controller sendSketchInfo("Energy_Temp_Hum", "1.0"); // Register all sensors to gw (they will be created as child devices) present(CHILD_ID_HUM, S_HUM); present(CHILD_ID_TEMP, S_TEMP); present(CHILD_ID_POW1, S_POWER); present(CHILD_ID_POW2, S_POWER); present(CHILD_ID_POW3, S_POWER); present(CHILD_ID_RSSI, S_CUSTOM); present(CHILD_ID_TEMP2, S_TEMP); } void loop() { Serial.print(hwMillis()); // for temporary tracing purposes Serial.println(" Sketch:Start of loop"); // for temporary tracing purposes float temperature = dht.readTemperature(); if (isnan(temperature)) { Serial.println("Failed reading temperature from DHT"); } else { send(msgTemp.set(temperature, 1)); } float humidity = dht.readHumidity(); if (isnan(humidity)) { Serial.println("Failed reading humidity from DHT"); } else { send(msgHum.set(humidity, 1)); } double Irms1 = ct1.calcIrms(1480); // calculate Irms phase1 double apparentPower1 = Irms1 * MEASURED_VOLTAGE; send(msgPower1.set(apparentPower1,1)); // send power consumption phase1 double Irms2 = ct2.calcIrms(1480); // calculate Irms phase2 double apparentPower2 = Irms2 * MEASURED_VOLTAGE; send(msgPower2.set(apparentPower2,1)); // send power consumption phase2 double Irms3 = ct3.calcIrms(1480); // calculate Irms phase 3 double apparentPower3 = Irms3 * MEASURED_VOLTAGE; send(msgPower3.set(apparentPower3,1)); // send power consumption phase3 rssi = _radio.readRSSI(); // read RSSI in RFM69 send(msgRSSI.set(rssi)); // send RSSI level temp2 = _radio.readTemperature(1); // read temperature in RFM69 send(msgTemp2.set(temp2)); // send temperature wait(SLEEP_TIME); //sleep a bit. } void receive(const MyMessage &message) { // We only expect one type of message from controller. But we better check anyway. Serial.println("something came in"); if (message.type==V_VAR1) { // reception to change SLEEP_TIME. SLEEP_TIME = message.getULong(); // send topic: eg. my_RFM69_gw1-in/3/1/1/0/24 30000 (payload in ms) } // MQTT_publish_topic_prefix/Node_Id/Sensor_Id/Cmd_Type/Ack_flag/type(V_VAR1=24) payload }
-
@Yveaux
The following trace is being captured:0 MCO:BGN:INIT NODE,CP=RRNNA--,VER=2.0.1-beta 4 init:MyLeds.cpp:ledsInit() var:prevTime=4294967221 preproc_const:LED_PROCESS_INTERVAL_MS=75 6 init:MyLeds.cpp:ledsPRocess() var:prevTime=0 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 17 TSM:INIT 25 TSM:INIT:TSP OK 26 TSM:INIT:STATID=3 28 TSF:SID:OK,ID=3 30 TSM:FPAR 31 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=0 var:end_sub:countTx=4 163 TSF:MSG:SEND,3-3-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK: 246 init:MyLeds.cpp:ledsBlinkRx() var:cnt=1 var:init_sub:countRx=0 var:end_sub:countRx=4 251 TSF:MSG:READ,0-0-3,s=255,c=3,t=8,pt=1,l=1,sg=0:0 259 TSF:MSG:FPAR OK,ID=0,D=1 2170 TSM:FPAR:OK 2171 TSM:ID 2172 TSM:ID:OK 2174 TSM:UPL 2176 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 2185 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1 2197 init:MyLeds.cpp:ledsBlinkRx() var:cnt=1 var:init_sub:countRx=4 var:end_sub:countRx=4 2202 TSF:MSG:READ,0-0-3,s=255,c=3,t=25,pt=1,l=1,sg=0:1 2209 TSF:MSG:PONG RECV,HP=1 2212 TSM:UPL:OK 2213 TSM:READY 2215 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 2225 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100 2232 init:MyLeds.cpp:ledsPRocess() var:prevTime=75 var:countRx=4 var:state=1 var:countTx=4 var:state=1 var:countErr=0 var:state=1 2238 init:MyLeds.cpp:ledsPRocess() var:prevTime=150 var:countRx=3 var:state=0 var:countTx=3 var:state=0 var:countErr=0 var:state=1 2249 init:MyLeds.cpp:ledsPRocess() var:prevTime=225 var:countRx=2 var:state=0 var:countTx=2 var:state=0 var:countErr=0 var:state=1 2262 init:MyLeds.cpp:ledsPRocess() var:prevTime=300 var:countRx=1 var:state=0 var:countTx=1 var:state=0 var:countErr=0 var:state=1 2274 init:MyLeds.cpp:ledsPRocess() var:prevTime=375 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2285 init:MyLeds.cpp:ledsBlinkRx() var:cnt=1 var:init_sub:countRx=0 var:end_sub:countRx=4 2295 TSF:MSG:READ,0-0-3,s=255,c=3,t=15,pt=6,l=2,sg=0:0100 2304 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=0 var:end_sub:countTx=4 2315 TSF:MSG:SEND,3-3-0-0,s=255,c=0,t=17,pt=0,l=10,sg=0,ft=0,st=OK:2.0.1-beta 2322 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 2374 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=0,st=OK:0 2380 init:MyLeds.cpp:ledsPRocess() var:prevTime=450 var:countRx=4 var:state=1 var:countTx=4 var:state=1 var:countErr=0 var:state=1 2386 init:MyLeds.cpp:ledsPRocess() var:prevTime=525 var:countRx=3 var:state=0 var:countTx=3 var:state=0 var:countErr=0 var:state=1 2399 init:MyLeds.cpp:ledsPRocess() var:prevTime=600 var:countRx=2 var:state=0 var:countTx=2 var:state=0 var:countErr=0 var:state=1 2410 init:MyLeds.cpp:ledsPRocess() var:prevTime=675 var:countRx=1 var:state=0 var:countTx=1 var:state=0 var:countErr=0 var:state=1 2422 init:MyLeds.cpp:ledsPRocess() var:prevTime=750 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2434 init:MyLeds.cpp:ledsPRocess() var:prevTime=825 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2446 init:MyLeds.cpp:ledsPRocess() var:prevTime=900 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2457 init:MyLeds.cpp:ledsPRocess() var:prevTime=975 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2469 init:MyLeds.cpp:ledsPRocess() var:prevTime=1050 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2481 init:MyLeds.cpp:ledsPRocess() var:prevTime=1125 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2493 init:MyLeds.cpp:ledsPRocess() var:prevTime=1200 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2505 init:MyLeds.cpp:ledsPRocess() var:prevTime=1275 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2516 init:MyLeds.cpp:ledsPRocess() var:prevTime=1350 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2529 init:MyLeds.cpp:ledsPRocess() var:prevTime=1425 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2541 init:MyLeds.cpp:ledsPRocess() var:prevTime=1500 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2552 init:MyLeds.cpp:ledsPRocess() var:prevTime=1575 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2565 init:MyLeds.cpp:ledsPRocess() var:prevTime=1650 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2576 init:MyLeds.cpp:ledsPRocess() var:prevTime=1725 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2588 init:MyLeds.cpp:ledsPRocess() var:prevTime=1800 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2600 init:MyLeds.cpp:ledsPRocess() var:prevTime=1875 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2612 init:MyLeds.cpp:ledsPRocess() var:prevTime=1950 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2624 init:MyLeds.cpp:ledsPRocess() var:prevTime=2025 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2635 init:MyLeds.cpp:ledsPRocess() var:prevTime=2100 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2648 init:MyLeds.cpp:ledsPRocess() var:prevTime=2175 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2660 init:MyLeds.cpp:ledsPRocess() var:prevTime=2250 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2671 init:MyLeds.cpp:ledsPRocess() var:prevTime=2325 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2683 init:MyLeds.cpp:ledsPRocess() var:prevTime=2400 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2696 init:MyLeds.cpp:ledsPRocess() var:prevTime=2475 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2707 init:MyLeds.cpp:ledsPRocess() var:prevTime=2550 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2719 init:MyLeds.cpp:ledsPRocess() var:prevTime=2625 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2731 init:MyLeds.cpp:ledsPRocess() var:prevTime=2700 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2743 init:MyLeds.cpp:ledsPRocess() 2746 init:MyLeds.cpp:ledsPRocess() 2749 init:MyLeds.cpp:ledsPRocess() 2752 init:MyLeds.cpp:ledsPRocess() 2755 init:MyLeds.cpp:ledsPRocess() 2758 init:MyLeds.cpp:ledsPRocess() 2761 init:MyLeds.cpp:ledsPRocess() 2764 init:MyLeds.cpp:ledsPRocess() 2767 init:MyLeds.cpp:ledsPRocess() 2770 init:MyLeds.cpp:ledsPRocess() 2774 init:MyLeds.cpp:ledsPRocess() var:prevTime=2775 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2786 init:MyLeds.cpp:ledsPRocess() 2789 init:MyLeds.cpp:ledsPRocess() 2792 init:MyLeds.cpp:ledsPRocess() 2795 init:MyLeds.cpp:ledsPRocess() 2798 init:MyLeds.cpp:ledsPRocess() 2801 init:MyLeds.cpp:ledsPRocess() 2803 init:MyLeds.cpp:ledsPRocess() 2806 init:MyLeds.cpp:ledsPRocess() 2809 init:MyLeds.cpp:ledsPRocess() 2812 init:MyLeds.cpp:ledsPRocess() 2816 init:MyLeds.cpp:ledsPRocess() 2819 init:MyLeds.cpp:ledsPRocess() 2822 init:MyLeds.cpp:ledsPRocess() 2825 init:MyLeds.cpp:ledsPRocess() 2828 init:MyLeds.cpp:ledsPRocess() 2831 init:MyLeds.cpp:ledsPRocess() 2834 init:MyLeds.cpp:ledsPRocess() 2837 init:MyLeds.cpp:ledsPRocess() 2840 init:MyLeds.cpp:ledsPRocess() 2843 init:MyLeds.cpp:ledsPRocess() 2846 init:MyLeds.cpp:ledsPRocess() 2849 init:MyLeds.cpp:ledsPRocess() var:prevTime=2850 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2862 init:MyLeds.cpp:ledsPRocess() 2865 init:MyLeds.cpp:ledsPRocess() 2868 init:MyLeds.cpp:ledsPRocess() 2871 init:MyLeds.cpp:ledsPRocess() 2874 init:MyLeds.cpp:ledsPRocess() 2877 init:MyLeds.cpp:ledsPRocess() 2880 init:MyLeds.cpp:ledsPRocess() 2883 init:MyLeds.cpp:ledsPRocess() 2886 init:MyLeds.cpp:ledsPRocess() 2889 init:MyLeds.cpp:ledsPRocess() 2892 init:MyLeds.cpp:ledsPRocess() 2895 init:MyLeds.cpp:ledsPRocess() 2898 init:MyLeds.cpp:ledsPRocess() 2902 init:MyLeds.cpp:ledsPRocess() 2905 init:MyLeds.cpp:ledsPRocess() 2908 init:MyLeds.cpp:ledsPRocess() 2911 init:MyLeds.cpp:ledsPRocess() 2914 init:MyLeds.cpp:ledsPRocess() 2917 init:MyLeds.cpp:ledsPRocess() 2920 init:MyLeds.cpp:ledsPRocess() 2923 init:MyLeds.cpp:ledsPRocess() var:prevTime=2925 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 ----(repeated behavior until 4378)---- 4361 init:MyLeds.cpp:ledsPRocess() 4364 init:MyLeds.cpp:ledsPRocess() 4367 init:MyLeds.cpp:ledsPRocess() 4369 init:MyLeds.cpp:ledsPRocess() 4372 init:MyLeds.cpp:ledsPRocess() 4375 init:MyLeds.cpp:ledsPRocess() 4378 init:MyLeds.cpp:ledsPRocess() 4381 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=0 var:end_sub:countTx=4 4399 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=11,pt=0,l=15,sg=0,ft=0,st=OK:Energy_Temp_Hum 4406 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4460 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=12,pt=0,l=3,sg=0,ft=0,st=OK:1.0 4466 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4518 TSF:MSG:SEND,3-3-0-0,s=0,c=0,t=7,pt=0,l=0,sg=0,ft=0,st=OK: 4525 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4577 TSF:MSG:SEND,3-3-0-0,s=1,c=0,t=6,pt=0,l=0,sg=0,ft=0,st=OK: 4583 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4635 TSF:MSG:SEND,3-3-0-0,s=6,c=0,t=13,pt=0,l=0,sg=0,ft=0,st=OK: 4641 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4694 TSF:MSG:SEND,3-3-0-0,s=7,c=0,t=13,pt=0,l=0,sg=0,ft=0,st=OK: 4700 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4751 TSF:MSG:SEND,3-3-0-0,s=8,c=0,t=13,pt=0,l=0,sg=0,ft=0,st=OK: 4757 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4811 TSF:MSG:SEND,3-3-0-0,s=4,c=0,t=23,pt=0,l=0,sg=0,ft=0,st=OK: 4816 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4870 TSF:MSG:SEND,3-3-0-0,s=5,c=0,t=6,pt=0,l=0,sg=0,ft=0,st=OK: 4876 MCO:REG:REQ 4877 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4931 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=26,pt=1,l=1,sg=0,ft=0,st=OK:2 4937 init:MyLeds.cpp:ledsPRocess() var:prevTime=4425 var:countRx=0 var:state=1 var:countTx=4 var:state=1 var:countErr=0 var:state=1 4943 init:MyLeds.cpp:ledsPRocess() var:prevTime=4500 var:countRx=0 var:state=1 var:countTx=3 var:state=0 var:countErr=0 var:state=1 4956 init:MyLeds.cpp:ledsPRocess() var:prevTime=4575 var:countRx=0 var:state=1 var:countTx=2 var:state=0 var:countErr=0 var:state=1 4967 init:MyLeds.cpp:ledsPRocess() var:prevTime=4650 var:countRx=0 var:state=1 var:countTx=1 var:state=0 var:countErr=0 var:state=1 4979 init:MyLeds.cpp:ledsPRocess() var:prevTime=4725 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 4992 init:MyLeds.cpp:ledsBlinkRx() var:cnt=1 var:init_sub:countRx=0 va nd_sub:countRx=4 5002 TSF:MSG:READ,0-0-3,s=255,c=3,t=27,pt=1,l=1,sg=0:1 5009 MCO:PIM:NODE REG=1 5012 MCO:BGN:STP 5013 MCO:BGN:INIT OK,ID=3,PAR=0,DIS=1,REG=1 5017 init:MyLeds.cpp:ledsPRocess() var:prevTime=4800 var:countRx=4 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 5023 Sketch:Start of loop 5298 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=0 var:end_sub:countTx=4 5307 TSF:MSG:SEND,3-3-0-0,s=1,c=1,t=0,pt=7,l=5,sg=0,ft=0,st=OK:25.2 5314 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 5367 TSF:MSG:SEND,3-3-0-0,s=0,c=1,t=1,pt=7,l=5,sg=0,ft=0,st=OK:41.7 5637 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 5647 TSF:MSG:SEND,3-3-0-0,s=6,c=1,t=17,pt=7,l=5,sg=0,ft=0,st=OK:53.2 5914 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 5924 TSF:MSG:SEND,3-3-0-0,s=7,c=1,t=17,pt=7,l=5,sg=0,ft=0,st=OK:79.9 6193 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 6204 TSF:MSG:SEND,3-3-0-0,s=8,c=1,t=17,pt=7,l=5,sg=0,ft=0,st=OK:4.5 6210 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 6305 TSF:MSG:SEND,3-3-0-0,s=4,c=1,t=24,pt=2,l=2,sg=0,ft=0,st=OK:-53 6311 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 6364 TSF:MSG:SEND,3-3-0-0,s=5,c=1,t=0,pt=2,l=2,sg=0,ft=0,st=OK:22 6370 init:MyLeds.cpp:ledsPRocess() var:prevTime=4875 var:countRx=3 var:state=0 var:countTx=4 var:state=1 var:countErr=0 var:state=1 6377 init:MyLeds.cpp:ledsPRocess() var:prevTime=4950 var:countRx=2 var:state=0 var:countTx=3 var:state=0 var:countErr=0 var:state=1 6388 init:MyLeds.cpp:ledsPRocess() var:prevTime=5025 var:countRx=1 var:state=0 var:countTx=2 var:state=0 var:countErr=0 var:state=1 6401 init:MyLeds.cpp:ledsPRocess() var:prevTime=5100 var:countRx=0 var:state=1 var:countTx=1 var:state=0 var:countErr=0 var:state=1 6412 init:MyLeds.cpp:ledsPRocess() var:prevTime=5175 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6424 init:MyLeds.cpp:ledsPRocess() var:prevTime=5250 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6436 init:MyLeds.cpp:ledsPRocess() var:prevTime=5325 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6448 init:MyLeds.cpp:ledsPRocess() var:prevTime=5400 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6460 init:MyLeds.cpp:ledsPRocess() var:prevTime=5475 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6471 init:MyLeds.cpp:ledsPRocess() var:prevTime=5550 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6483 init:MyLeds.cpp:ledsPRocess() var:prevTime=5625 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6496 init:MyLeds.cpp:ledsPRocess() var:prevTime=5700 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6507 init:MyLeds.cpp:ledsPRocess() var:prevTime=5775 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6519 init:MyLeds.cpp:ledsPRocess() var:prevTime=5850 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6532 init:MyLeds.cpp:ledsPRocess() var:prevTime=5925 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6543 init:MyLeds.cpp:ledsPRocess() var:prevTime=6000 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6555 init:MyLeds.cpp:ledsPRocess() var:prevTime=6075 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6566 init:MyLeds.cpp:ledsPRocess() var:prevTime=6150 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6579 init:MyLeds.cpp:ledsPRocess() var:prevTime=6225 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6591 init:MyLeds.cpp:ledsPRocess() var:prevTime=6300 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6602 init:MyLeds.cpp:ledsPRocess() var:prevTime=6375 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6615 init:MyLeds.cpp:ledsPRocess() var:prevTime=6450 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6627 init:MyLeds.cpp:ledsPRocess() var:prevTime=6525 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6638 init:MyLeds.cpp:ledsPRocess() var:prevTime=6600 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6650 init:MyLeds.cpp:ledsPRocess() 6653 init:MyLeds.cpp:ledsPRocess() 6657 init:MyLeds.cpp:ledsPRocess() 6660 init:MyLeds.cpp:ledsPRocess() 6663 init:MyLeds.cpp:ledsPRocess() 6666 init:MyLeds.cpp:ledsPRocess() 6669 init:MyLeds.cpp:ledsPRocess() 6672 init:MyLeds.cpp:ledsPRocess()
-
@Yveaux
Some erroneous behaviors are identified:
At ms 2232 during the internal startup phase of MySensors, variable prevTime=75 and hwMillis=2232. The Tx-led and Rx-led are turned-on as expected at ms 2238. From here-on some cat and mouse situation starts, adding to prevTime +75ms every 10-20ms in routine ledsProcess(), starting to slowly catch up with the hwMillis() value, and as well an unnecessary hwWrite is performed on the LEDs at every cycle. After 3 cycles the Tx-led and Rx-led are turned off again at ms 2274, after 36ms.At ms 2380 the same situation occurs, turning on the tx-led and turning it off again after 42ms.
Those cases occur before starting the loop().
At ms 2743 the variable prevTime catches up with hwMillis.At ms 4399 the presentations() start and the out of track, cat and mouse situation, starts again between prevTime and hwMillis().
At ms 5023 the loop starts. Similar erroneous behaviors starts to occur. At ms 6650 it catches up and starts a momentaneous expected behaviour. The Tx-led is turned on for 42ms. Similar situation happens with the Rx-led at ms 6370.
Adding the patch mentioned above to the MyLeds.cpp file gets the following log:
0 MCO:BGN:INIT NODE,CP=RRNNA--,VER=2.0.1-beta 4 init:MyLeds.cpp:ledsInit() var:prevTime=4294967221 preproc_const:LED_PROCESS_INTERVAL_MS=75 6 init:MyLeds.cpp:ledsPRocess() var:prevTime=9 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 17 TSM:INIT 25 TSM:INIT:TSP OK 26 TSM:INIT:STATID=3 28 TSF:SID:OK,ID=3 30 TSM:FPAR 31 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=0 var:end_sub:countTx=4 163 TSF:MSG:SEND,3-3-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK: 893 init:MyLeds.cpp:ledsBlinkRx() var:cnt=1 var:init_sub:countRx=0 var:end_sub:countRx=4 899 TSF:MSG:READ,0-0-3,s=255,c=3,t=8,pt=1,l=1,sg=0:0 906 TSF:MSG:FPAR OK,ID=0,D=1 2170 TSM:FPAR:OK 2171 TSM:ID 2172 TSM:ID:OK 2174 TSM:UPL 2176 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 2185 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1 2198 init:MyLeds.cpp:ledsBlinkRx() var:cnt=1 var:init_sub:countRx=4 var:end_sub:countRx=4 2203 TSF:MSG:READ,0-0-3,s=255,c=3,t=25,pt=1,l=1,sg=0:1 2210 TSF:MSG:PONG RECV,HP=1 2213 TSM:UPL:OK 2214 TSM:READY 2216 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 2226 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100 2232 init:MyLeds.cpp:ledsPRocess() var:prevTime=2233 var:countRx=4 var:state=1 var:countTx=4 var:state=1 var:countErr=0 var:state=1 2239 init:MyLeds.cpp:ledsPRocess() 2242 init:MyLeds.cpp:ledsPRocess() 2245 init:MyLeds.cpp:ledsPRocess() 2248 init:MyLeds.cpp:ledsPRocess() 2251 init:MyLeds.cpp:ledsPRocess() 2254 init:MyLeds.cpp:ledsPRocess() 2257 init:MyLeds.cpp:ledsPRocess() 2260 init:MyLeds.cpp:ledsPRocess() 2264 init:MyLeds.cpp:ledsPRocess() 2267 init:MyLeds.cpp:ledsPRocess() 2270 init:MyLeds.cpp:ledsPRocess() 2273 init:MyLeds.cpp:ledsPRocess() 2276 init:MyLeds.cpp:ledsPRocess() 2279 init:MyLeds.cpp:ledsBlinkRx() var:cnt=1 var:init_sub:countRx=3 var:end_sub:countRx=3 2289 TSF:MSG:READ,0-0-3,s=255,c=3,t=15,pt=6,l=2,sg=0:0100 2297 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=3 var:end_sub:countTx=3 2308 TSF:MSG:SEND,3-3-0-0,s=255,c=0,t=17,pt=0,l=10,sg=0,ft=0,st=OK:2.0.1-beta 2315 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=3 var:end_sub:countTx=3 2367 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=0,st=OK:0 2373 init:MyLeds.cpp:ledsPRocess() var:prevTime=2374 var:countRx=3 var:state=0 var:countTx=3 var:state=0 var:countErr=0 var:state=1 2380 init:MyLeds.cpp:ledsPRocess() 2383 init:MyLeds.cpp:ledsPRocess() 2386 init:MyLeds.cpp:ledsPRocess() 2390 init:MyLeds.cpp:ledsPRocess() 2393 init:MyLeds.cpp:ledsPRocess() 2396 init:MyLeds.cpp:ledsPRocess() 2399 init:MyLeds.cpp:ledsPRocess() 2402 init:MyLeds.cpp:ledsPRocess() 2405 init:MyLeds.cpp:ledsPRocess() 2408 init:MyLeds.cpp:ledsPRocess() 2411 init:MyLeds.cpp:ledsPRocess() 2414 init:MyLeds.cpp:ledsPRocess() 2417 init:MyLeds.cpp:ledsPRocess() 2420 init:MyLeds.cpp:ledsPRocess() 2423 init:MyLeds.cpp:ledsPRocess() 2426 init:MyLeds.cpp:ledsPRocess() 2429 init:MyLeds.cpp:ledsPRocess() 2433 init:MyLeds.cpp:ledsPRocess() 2436 init:MyLeds.cpp:ledsPRocess() 2439 init:MyLeds.cpp:ledsPRocess() 2442 init:MyLeds.cpp:ledsPRocess() 2445 init:MyLeds.cpp:ledsPRocess() 2448 init:MyLeds.cpp:ledsPRocess() var:prevTime=2451 var:countRx=2 var:state=0 var:countTx=2 var:state=0 var:countErr=0 var:state=1 2459 init:MyLeds.cpp:ledsPRocess() 2462 init:MyLeds.cpp:ledsPRocess() 2465 init:MyLeds.cpp:ledsPRocess() 2468 init:MyLeds.cpp:ledsPRocess() 2471 init:MyLeds.cpp:ledsPRocess() 2475 init:MyLeds.cpp:ledsPRocess() 2478 init:MyLeds.cpp:ledsPRocess() 2481 init:MyLeds.cpp:ledsPRocess() 2484 init:MyLeds.cpp:ledsPRocess() 2487 init:MyLeds.cpp:ledsPRocess() 2490 init:MyLeds.cpp:ledsPRocess() 2493 init:MyLeds.cpp:ledsPRocess() 2496 init:MyLeds.cpp:ledsPRocess() 2499 init:MyLeds.cpp:ledsPRocess() 2502 init:MyLeds.cpp:ledsPRocess() 2505 init:MyLeds.cpp:ledsPRocess() 2508 init:MyLeds.cpp:ledsPRocess() 2511 init:MyLeds.cpp:ledsPRocess() 2514 init:MyLeds.cpp:ledsPRocess() 2518 init:MyLeds.cpp:ledsPRocess() 2521 init:MyLeds.cpp:ledsPRocess() 2524 init:MyLeds.cpp:ledsPRocess() var:prevTime=2527 var:countRx=1 var:state=0 var:countTx=1 var:state=0 var:countErr=0 var:state=1 2536 init:MyLeds.cpp:ledsPRocess() 2539 init:MyLeds.cpp:ledsPRocess() 2542 init:MyLeds.cpp:ledsPRocess() 2544 init:MyLeds.cpp:ledsPRocess() 2547 init:MyLeds.cpp:ledsPRocess() 2550 init:MyLeds.cpp:ledsPRocess() 2553 init:MyLeds.cpp:ledsPRocess() 2556 init:MyLeds.cpp:ledsPRocess() 2560 init:MyLeds.cpp:ledsPRocess() 2563 init:MyLeds.cpp:ledsPRocess() 2566 init:MyLeds.cpp:ledsPRocess() 2569 init:MyLeds.cpp:ledsPRocess() 2572 init:MyLeds.cpp:ledsPRocess() 2575 init:MyLeds.cpp:ledsPRocess() 2578 init:MyLeds.cpp:ledsPRocess() 2581 init:MyLeds.cpp:ledsPRocess() 2584 init:MyLeds.cpp:ledsPRocess() 2587 init:MyLeds.cpp:ledsPRocess() 2590 init:MyLeds.cpp:ledsPRocess() 2593 init:MyLeds.cpp:ledsPRocess() 2596 init:MyLeds.cpp:ledsPRocess() 2599 init:MyLeds.cpp:ledsPRocess() var:prevTime=2603 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1 2612 init:MyLeds.cpp:ledsPRocess() ---- (same repeating behavior until 4376)---- 4372 init:MyLeds.cpp:ledsPRocess() 4376 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=0 var:end_sub:countTx=4 4392 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=11,pt=0,l=15,sg=0,ft=0,st=OK:Energy_Temp_Hum 4401 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4454 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=12,pt=0,l=3,sg=0,ft=0,st=OK:1.0 4460 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4512 TSF:MSG:SEND,3-3-0-0,s=0,c=0,t=7,pt=0,l=0,sg=0,ft=0,st=OK: 4517 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4571 TSF:MSG:SEND,3-3-0-0,s=1,c=0,t=6,pt=0,l=0,sg=0,ft=0,st=OK: 4577 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4629 TSF:MSG:SEND,3-3-0-0,s=6,c=0,t=13,pt=0,l=0,sg=0,ft=0,st=OK: 4635 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4687 TSF:MSG:SEND,3-3-0-0,s=7,c=0,t=13,pt=0,l=0,sg=0,ft=0,st=OK: 4694 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4746 TSF:MSG:SEND,3-3-0-0,s=8,c=0,t=13,pt=0,l=0,sg=0,ft=0,st=OK: 4752 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4804 TSF:MSG:SEND,3-3-0-0,s=4,c=0,t=23,pt=0,l=0,sg=0,ft=0,st=OK: 4810 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4862 TSF:MSG:SEND,3-3-0-0,s=5,c=0,t=6,pt=0,l=0,sg=0,ft=0,st=OK: 4869 MCO:REG:REQ 4870 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=4 var:end_sub:countTx=4 4924 TSF:MSG:SEND,3-3-0-0,s=255,c=3,t=26,pt=1,l=1,sg=0,ft=0,st=OK:2 4930 init:MyLeds.cpp:ledsPRocess() var:prevTime=4930 var:countRx=0 var:state=1 var:countTx=4 var:state=1 var:countErr=0 var:state=1 4936 init:MyLeds.cpp:ledsPRocess() 4939 init:MyLeds.cpp:ledsPRocess() 4942 init:MyLeds.cpp:ledsPRocess() 4945 init:MyLeds.cpp:ledsPRocess() 4948 init:MyLeds.cpp:ledsPRocess() 4952 init:MyLeds.cpp:ledsPRocess() 4955 init:MyLeds.cpp:ledsPRocess() 4958 init:MyLeds.cpp:ledsPRocess() 4961 init:MyLeds.cpp:ledsPRocess() 4964 init:MyLeds.cpp:ledsPRocess() 4967 init:MyLeds.cpp:ledsPRocess() 4970 init:MyLeds.cpp:ledsPRocess() 4973 init:MyLeds.cpp:ledsPRocess() 4976 init:MyLeds.cpp:ledsBlinkRx() var:cnt=1 var:init_sub:countRx=0 var:end_sub:countRx=4 4986 TSF:MSG:READ,0-0-3,s=255,c=3,t=27,pt=1,l=1,sg=0:1 4995 MCO:PIM:NODE REG=1 4997 MCO:BGN:STP 4999 MCO:BGN:INIT OK,ID=3,PAR=0,DIS=1,REG=1 5002 init:MyLeds.cpp:ledsPRocess() 5003 Sketch:Start of loop 5274 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=3 var:end_sub:countTx=3 5284 TSF:MSG:SEND,3-3-0-0,s=1,c=1,t=0,pt=7,l=5,sg=0,ft=0,st=OK:25.1 5291 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=3 var:end_sub:countTx=3 5346 TSF:MSG:SEND,3-3-0-0,s=0,c=1,t=1,pt=7,l=5,sg=0,ft=0,st=OK:42.2 5614 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=3 var:end_sub:countTx=3 5625 TSF:MSG:SEND,3-3-0-0,s=6,c=1,t=17,pt=7,l=5,sg=0,ft=0,st=OK:53.3 5893 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=3 var:end_sub:countTx=3 5903 TSF:MSG:SEND,3-3-0-0,s=7,c=1,t=17,pt=7,l=5,sg=0,ft=0,st=OK:79.9 6136 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=3 var:end_sub:countTx=3 6148 TSF:MSG:SEND,3-3-0-0,s=8,c=1,t=17,pt=7,l=5,sg=0,ft=0,st=OK:0.0 6154 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=3 var:end_sub:countTx=3 6206 TSF:MSG:SEND,3-3-0-0,s=4,c=1,t=24,pt=2,l=2,sg=0,ft=0,st=OK:-56 6213 init:MyLeds.cpp:ledsBlinkTx() var:cnt=1 var:init_sub:countTx=3 var:end_sub:countTx=3 6265 TSF:MSG:SEND,3-3-0-0,s=5,c=1,t=0,pt=2,l=2,sg=0,ft=0,st=OK:21 6272 init:MyLeds.cpp:ledsPRocess() var:prevTime=6272 var:countRx=4 var:state=1 var:countTx=3 var:state=0 var:countErr=0 var:state=1 6278 init:MyLeds.cpp:ledsPRocess() 6281 init:MyLeds.cpp:ledsPRocess() 6284 init:MyLeds.cpp:ledsPRocess() 6287 init:MyLeds.cpp:ledsPRocess() 6290 init:MyLeds.cpp:ledsPRocess() 6293 init:MyLeds.cpp:ledsPRocess() 6296 init:MyLeds.cpp:ledsPRocess() 6299 init:MyLeds.cpp:ledsPRocess() 6302 init:MyLeds.cpp:ledsPRocess() 6305 init:MyLeds.cpp:ledsPRocess() 6308 init:MyLeds.cpp:ledsPRocess() 6311 init:MyLeds.cpp:ledsPRocess() 6315 init:MyLeds.cpp:ledsPRocess() 6318 init:MyLeds.cpp:ledsPRocess() 6321 init:MyLeds.cpp:ledsPRocess() 6324 init:MyLeds.cpp:ledsPRocess() 6327 init:MyLeds.cpp:ledsPRocess() 6330 init:MyLeds.cpp:ledsPRocess() 6333 init:MyLeds.cpp:ledsPRocess() 6336 init:MyLeds.cpp:ledsPRocess() 6339 init:MyLeds.cpp:ledsPRocess() 6342 init:MyLeds.cpp:ledsPRocess() 6345 init:MyLeds.cpp:ledsPRocess() var:prevTime=6348 var:countRx=3 var:state=0 var:countTx=2 var:state=0 var:countErr=0 var:state=1 6358 init:MyLeds.cpp:ledsPRocess() 6360 init:MyLeds.cpp:ledsPRocess() 6363 init:MyLeds.cpp:ledsPRocess() 6366 init:MyLeds.cpp:ledsPRocess() 6369 init:MyLeds.cpp:ledsPRocess() 6372 init:MyLeds.cpp:ledsPRocess() 6375 init:MyLeds.cpp:ledsPRocess() 6378 init:MyLeds.cpp:ledsPRocess() 6381 init:MyLeds.cpp:ledsPRocess() 6384 init:MyLeds.cpp:ledsPRocess() 6387 init:MyLeds.cpp:ledsPRocess() 6390 init:MyLeds.cpp:ledsPRocess() 6393 init:MyLeds.cpp:ledsPRocess() 6396 init:MyLeds.cpp:ledsPRocess() 6400 init:MyLeds.cpp:ledsPRocess() 6403 init:MyLeds.cpp:ledsPRocess() 6406 init:MyLeds.cpp:ledsPRocess() 6409 init:MyLeds.cpp:ledsPRocess() 6412 init:MyLeds.cpp:ledsPRocess() 6415 init:MyLeds.cpp:ledsPRocess() 6418 init:MyLeds.cpp:ledsPRocess() 6421 init:MyLeds.cpp:ledsPRocess() var:prevTime=6424 var:countRx=2 var:state=0 var:countTx=1 var:state=0 var:countErr=0 var:state=1 6433 init:MyLeds.cpp:ledsPRocess() 6436 init:MyLeds.cpp:ledsPRocess() 6439 init:MyLeds.cpp:ledsPRocess() 6443 init:MyLeds.cpp:ledsPRocess() 6446 init:MyLeds.cpp:ledsPRocess() 6449 init:MyLeds.cpp:ledsPRocess() 6452 init:MyLeds.cpp:ledsPRocess() 6455 init:MyLeds.cpp:ledsPRocess() 6458 init:MyLeds.cpp:ledsPRocess() 6461 init:MyLeds.cpp:ledsPRocess() 6464 init:MyLeds.cpp:ledsPRocess() 6467 init:MyLeds.cpp:ledsPRocess() 6470 init:MyLeds.cpp:ledsPRocess() 6473 init:MyLeds.cpp:ledsPRocess() 6476 init:MyLeds.cpp:ledsPRocess() 6479 init:MyLeds.cpp:ledsPRocess() 6482 init:MyLeds.cpp:ledsPRocess() 6486 init:MyLeds.cpp:ledsPRocess() 6489 init:MyLeds.cpp:ledsPRocess() 6492 init:MyLeds.cpp:ledsPRocess() 6495 init:MyLeds.cpp:ledsPRocess() 6498 init:MyLeds.cpp:ledsPRocess() var:prevTime=6501 var:countRx=1 var:state=0 var:countTx=0 var:state=1 var:countErr=0 var:state=1 6509 init:MyLeds.cpp:ledsPRocess() 6512 init:MyLeds.cpp:ledsPRocess() 6515 init:MyLeds.cpp:ledsPRocess() 6518 init:MyLeds.cpp:ledsPRocess() 6521 init:MyLeds.cpp:ledsPRocess() 6524 init:MyLeds.cpp:ledsPRocess() 6528 init:MyLeds.cpp:ledsPRocess() 6531 init:MyLeds.cpp:ledsPRocess() 6534 init:MyLeds.cpp:ledsPRocess() 6537 init:MyLeds.cpp:ledsPRocess() 6540 init:MyLeds.cpp:ledsPRocess() 6543 init:MyLeds.cpp:ledsPRocess() 6546 init:MyLeds.cpp:ledsPRocess() 6549 init:MyLeds.cpp:ledsPRocess() 6552 init:MyLeds.cpp:ledsPRocess() 6555 init:MyLeds.cpp:ledsPRocess() 6558 init:MyLeds.cpp:ledsPRocess() 6561 init:MyLeds.cpp:ledsPRocess() 6564 init:MyLeds.cpp:ledsPRocess() 6567 init:MyLeds.cpp:ledsPRocess() 6571 init:MyLeds.cpp:ledsPRocess() 6574 init:MyLeds.cpp:ledsPRocess() var:prevTime=6577 var:countRx=0 var:state=1 var:countTx=0 var:state=1 var:countErr=0 var:state=1Now in the trace the "out-of-track" behaviours disappears. The LEDs starts to, in my tests, inform the same information as the debug traces. Independently if the loop() is short or long. As well in the start-up phases the LEDs are now acting in a normal fashion.
Please give your feed back if you see some other aspects and maybe identifies a different soluition to this, as far as I can see, software bug.
-
@jpaulin The issue is initiated because the library does not call the ledsProcess() during the startup phase, even though messages are exchanged and leds should blink. This causes prevTime to lag behind for more than 2 seconds.
It takes a while to catch up (at 2743), runs well for a while (ledsProcess() is now called every 3 ms) and then starts lagging behind again, at 4378 as you say.Your solution indeed prevents lagging behind, but also doesn't guarantee accurate timing when ledsProcess() simply isn't called, or is called at intervals far greater than LED_PROCESS_INTERVAL_MS.
For the application it's up to the user, but the MySensors library should not 'forget' to update the leds during startup and long wait cycles.
I saw @tbowmo already pushed your fix, but I think we should have a better look at it as I feel it can be solved in a better way.
-
@jpaulin Could you give my branch https://github.com/Yveaux/MySensors/tree/ledProcess_fix a try?
It should improve calling a.o. the ledsProcess() from the stack.
I haven't had the time to test it yet, though
-
@Yveaux
I tested your branch, both on a node and a gw. In general it works pretty well. Some improvements on the leds can be identified.
I tested with MY_DEFAULT_LED_BLINK_PERIOD set to 50, 300 and 600 (both on the node and the gw), and I tested on the node with wait(), sleep() and smartSleep() in the loop(). I'm using 7 send() per cycle in the loop() before going to sleep(), smartSleep() or wait().-
Before, on the node, the tx-led was turned on after the loop(), in wait(). Now it turns on during the loop(), nice.
-
Using sleep() the led(s) mostly gets stuck in an ON state during sleep(). This happened before as well on the development branch.
-
Using smartSleep() normally it works well as long as MY_DEFAULT_LED_BLINK_PERIOD is shorter than MY_SMART_SLEEP_WAIT_DURATION_MS. This could, I guess, partially be solved with a conditional test at line 516 in MySensorsCore.cpp, to wait for the longest of the two constants mentioned. As long as no message arrives during the wait(). Or maybe a generic solution for sleep() and smartSleep() could be added at line 520 in MySensorsCore.cpp, with eg. a "while (LEDs are still ON?) { _process(); }" before executing transportPowerDown(); on line 521, or something similar.
-
I suspect there's a (minor) risk with the line added at line 48 in MyLeds.cpp , to fail at line 54 . If hwMillis() is greater than LED_PROCESS_INTERVAL_MS it would fail. I'd recommend to better change line 48:
from:
prevTime = hwMillis() - LED_PROCESS_INTERVAL_MS; // Substract some, to make sure leds gets updated on first run.to:
prevTime = hwMillis(); // Make sure leds gets updated on first run.-
Setting MY_DEFAULT_LED_BLINK_PERIOD to 50 on the gw, the leds on the gw manages to blink on every single message, looks really nice.
Both for internal messages on the gw/nodes, and for sketch messages on the nodes. -
On the node with my 7 send(), only two longer tx-blinks happens per loop() cycle. This is due to the ledProcess() has to be passed 4 times to finish a led cycle (on,on,on,off). This I guess could be optimized to one cycle per ledProcess(), or trying to pass ledProcess() more frequently during the loop() cycle. I'm not sure how to fix it without some major changes. It's no big deal. Maybe it's just a "too-nice-to-have".
-
Your fixes for an ESP8266 gw can't unfortunately be verified. I'm using an mqtt-client RF69W ethernet gw.
-
-
@jpaulin said:
I tested your branch, both on a node and a gw. In general it works pretty well. Some improvements on the leds can be identified.
Good to hear
Using sleep() the led(s) mostly gets stuck in an ON state during sleep(). This happened before as well on the development branch.
Yes, I realized this while changing the code. This 'feature' is indeed also present in the current library. I think it is a separate issue: https://github.com/mysensors/MySensors/issues/639
Using smartSleep() normally it works well as long as MY_DEFAULT_LED_BLINK_PERIOD is shorter than MY_SMART_SLEEP_WAIT_DURATION_MS. This could, I guess, partially be solved with a conditional test at line 516 in MySensorsCore.cpp, to wait for the longest of the two constants mentioned. As long as no message arrives during the wait(). Or maybe a generic solution for sleep() and smartSleep() could be added at line 520 in MySensorsCore.cpp, with eg. a "while (LEDs are still ON?) { _process(); }" before executing transportPowerDown(); on line 521, or something similar.
Don't expect LED blinking to continue correctly after lower-power sleep()-ing.
The millis() function does not update during sleep, so the LED blinking pattern will not recover after wake from sleep.
We could either first finish the pattern before going to sleep, or stop the pattern (and turn the LEDs off) when going to sleep.I suspect there's a (minor) risk with the line added at line 48 in MyLeds.cpp , to fail at line 54 . If hwMillis() is greater than LED_PROCESS_INTERVAL_MS it would fail. I'd recommend to better change line 48:
from:
prevTime = hwMillis() - LED_PROCESS_INTERVAL_MS; // Substract some, to make sure leds gets updated on first run.
to:prevTime = hwMillis(); // Make sure leds gets updated on first run.
This makes things worse; LEDs will not be initialized on first call to ledsProcess, but after LED_PROCESS_INTERVAL_MS:
in ledsInit():
prevTime = hwMillis() - LED_PROCESS_INTERVAL_MSthus
hwMillis() - prevTime == LED_PROCESS_INTERVAL_MSThen, in ledsProcess:
if ((hwMillis() - prevTime) < LED_PROCESS_INTERVAL_MS) {substituting 'hwMillis() - prevTime'
if (LED_PROCESS_INTERVAL_MS < LED_PROCESS_INTERVAL_MS) {which is always false. Even if millis() increased inbetween this statement will still be false and so the LED update code will always be called on first run.
I normally prefer clear code (e.g. using a flag to trigger the initial setup), but this saves some ram...On the node with my 7 send(), only two longer tx-blinks happens per loop() cycle. This is due to the ledProcess() has to be passed 4 times to finish a led cycle (on,on,on,off). This I guess could be optimized to one cycle per ledProcess(), or trying to pass ledProcess() more frequently during the loop() cycle. I'm not sure how to fix it without some major changes. It's no big deal. Maybe it's just a "too-nice-to-have".
You could try setting LED_ON_OFF_RATIO to 2, to use a shorter cycle.
Or, change the ledsBlinkxx() functions to something like:void ledsBlinkRx(uint8_t cnt) { countRx += cnt*LED_ON_OFF_RATIO; ledsProcess(); }to implement 'poor man's' queuing of LED flashes.
Your fixes for an ESP8266 gw can't unfortunately be verified. I'm using an mqtt-client RF69W ethernet gw.
Ok, thanks for testing and reporting so far!
-
@jpaulin Fix is now in development (also tested on ESP8266) and sleeping issue is also solved.
Node will now finish its LED pattern before going to sleep.
