Firmware 151 takes 9seconds to boot verses 150 3seconds

johnnyfp · May 14, 2020, 1:29am

Hi,
I’ve recently updated to the latest release of the firmware (v1.5.1) and have noticed that my setup is taking nearly 9 seconds to boot. Below is a sample output of the following code that I’ve run on both firmware versions.
I can fix this and speed things up by single_threading my routine, but would like to try and avoid that. Any ideas as to why this is happening?

Code used

SYSTEM_THREAD(ENABLED);
SYSTEM_MODE(MANUAL);

Logger lu("lu");
StreamLogHandler* loggingHandler;

void scan_i2c_bus() {
  lu("Scanning I2C bus");
  String found;
  String errors;

  SINGLE_THREADED_BLOCK(){ //Remove to slow startup down.
    for(int address = 1; address < 127; address++ )
    {
      Wire.beginTransmission(address);
      uint8_t error = Wire.endTransmission();
      lu("Processing :%d",address);
      if (error == 0)
      {
        found += String::format("[%02x]", address);
      }
      else if (error==4)
      {
        
        errors += String::format("[%02x]", address);
      }    
    }
  }
  
  lu("I2C devices at addr %s", found.c_str());
  if (errors.length() > 0) {
    lu("I2C errors at addr %s", errors.c_str());
  }
  lu("Finished scanning I2C bus");
}

void setup() {
  WiFi.off();
  loggingHandler=new Serial1LogHandler(57600,LOG_LEVEL_ALL,{{ "lu",LOG_LEVEL_ALL}});
  Wire.begin();
  scan_i2c_bus();
  lu("Done Setup");
}


void loop() {
  delay(5000);
}

Output from code without single_threaded_block

0000000272 [lu] INFO: Scanning I2C bus
0000000324 [lu] INFO: Processing :1
0000000376 [lu] INFO: Processing :2
0000000428 [lu] INFO: Processing :3
0000000480 [lu] INFO: Processing :4
0000000532 [lu] INFO: Processing :5
0000001563 [ncp.at] TRACE: > AT
0000001564 [ncp.at] TRACE: < OK
0000002564 [hal] TRACE: NCP ready to accept AT commands
0000002564 [ncp.at] TRACE: > AT+CMUX=0
0000002566 [ncp.at] TRACE: < OK
0000002568 [gsm0710muxer] INFO: Starting GSM07.10 muxer
0000002580 [gsm0710muxer] INFO: Openning mux channel 0
0000002580 [gsm0710muxer] INFO: GSM07.10 muxer thread started
0000002603 [lu] INFO: Processing :6
0000002652 [gsm0710muxer] INFO: Resuming channel 0
0000002652 [gsm0710muxer] INFO: Openning mux channel 1
0000002654 [lu] INFO: Processing :7
0000002722 [lu] INFO: Processing :8
0000002753 [gsm0710muxer] INFO: Resuming channel 1
0000002753 [gsm0710muxer] INFO: Resuming channel 1
0000002754 [ncp.at] TRACE: > AT
0000002774 [lu] INFO: Processing :9
0000002806 [ncp.at] TRACE: < OK
0000002806 [ncp.at] TRACE: > AT+CWDHCP=0,3
0000002826 [lu] INFO: Processing :10
0000002856 [ncp.at] TRACE: < OK
0000002856 [hal] TRACE: NCP state changed: 1
0000002856 [net.esp32ncp] TRACE: NCP event 1
0000002857 [ncp.at] TRACE: > AT+GETMAC=0
0000002878 [lu] INFO: Processing :11
0000002906 [ncp.at] TRACE: < +GETMAC: "30:ae:a4:d1:f7:cc"
0000002906 [ncp.at] TRACE: < OK
0000002907 [gsm0710muxer] INFO: Stopping GSM07.10 muxer
0000002911 [gsm0710muxer] INFO: Gracefully stopping GSM07.10 muxer
0000002923 [gsm0710muxer] INFO: Closing all muxed channels
0000002933 [gsm0710muxer] INFO: Closing mux channel 1
0000002946 [gsm0710muxer] INFO: Muxed channel 2 already closed
0000002955 [gsm0710muxer] INFO: Muxed channel 3 already closed
0000002968 [gsm0710muxer] INFO: Muxed channel 4 already closed
0000002978 [lu] INFO: Processing :12
0000003041 [lu] INFO: Processing :13
0000003078 [gsm0710muxer] INFO: Sending CLD (multiplexer close down)
0000003093 [lu] INFO: Processing :14
0000003128 [gsm0710muxer] INFO: Received response to CLD or timed out, exiting multiplexed mode
0000003128 [gsm0710muxer] INFO: GSM07.10 muxer thread exiting
0000003154 [gsm0710muxer] INFO: GSM07.10 muxer stopped
0000003155 [hal] TRACE: NCP state changed: 0
0000003155 [net.esp32ncp] TRACE: NCP event 1
0000003168 [lu] INFO: Processing :15
0000003219 [lu] INFO: Processing :16
0000003271 [lu] INFO: Processing :17
0000003323 [lu] INFO: Processing :18
0000003375 [lu] INFO: Processing :19
0000003428 [lu] INFO: Processing :20
0000003479 [lu] INFO: Processing :21
0000003531 [lu] INFO: Processing :22
0000003583 [lu] INFO: Processing :23
0000003635 [lu] INFO: Processing :24
0000003636 [lu] INFO: Processing :25
0000003688 [lu] INFO: Processing :26
0000003740 [lu] INFO: Processing :27
0000003792 [lu] INFO: Processing :28
0000003844 [lu] INFO: Processing :29
0000003896 [lu] INFO: Processing :30
0000003948 [lu] INFO: Processing :31
0000004000 [lu] INFO: Processing :32
0000004053 [lu] INFO: Processing :33
0000004104 [lu] INFO: Processing :34
0000004156 [lu] INFO: Processing :35
0000004208 [lu] INFO: Processing :36
0000004260 [lu] INFO: Processing :37
0000004312 [lu] INFO: Processing :38
0000004364 [lu] INFO: Processing :39
0000004416 [lu] INFO: Processing :40
0000004468 [lu] INFO: Processing :41
0000004520 [lu] INFO: Processing :42
0000004572 [lu] INFO: Processing :43
0000004624 [lu] INFO: Processing :44
0000004676 [lu] INFO: Processing :45
0000004728 [lu] INFO: Processing :46
0000004780 [lu] INFO: Processing :47
0000004832 [lu] INFO: Processing :48
0000004884 [lu] INFO: Processing :49
0000004936 [lu] INFO: Processing :50
0000004988 [lu] INFO: Processing :51
0000005040 [lu] INFO: Processing :52
0000005092 [lu] INFO: Processing :53
0000005093 [lu] INFO: Processing :54
0000005145 [lu] INFO: Processing :55
0000005146 [lu] INFO: Processing :56
0000005198 [lu] INFO: Processing :57
0000005250 [lu] INFO: Processing :58
0000005303 [lu] INFO: Processing :59
0000005354 [lu] INFO: Processing :60
0000005406 [lu] INFO: Processing :61
0000005458 [lu] INFO: Processing :62
0000005510 [lu] INFO: Processing :63
0000005511 [lu] INFO: Processing :64
0000005512 [lu] INFO: Processing :65
0000005563 [lu] INFO: Processing :66
0000005615 [lu] INFO: Processing :67
0000005616 [lu] INFO: Processing :68
0000005617 [lu] INFO: Processing :69
0000005668 [lu] INFO: Processing :70
0000005720 [lu] INFO: Processing :71
0000005772 [lu] INFO: Processing :72
0000005824 [lu] INFO: Processing :73
0000005876 [lu] INFO: Processing :74
0000005928 [lu] INFO: Processing :75
0000005980 [lu] INFO: Processing :76
0000006032 [lu] INFO: Processing :77
0000006084 [lu] INFO: Processing :78
0000006136 [lu] INFO: Processing :79
0000006137 [lu] INFO: Processing :80
0000006138 [lu] INFO: Processing :81
0000006189 [lu] INFO: Processing :82
0000006241 [lu] INFO: Processing :83
0000006293 [lu] INFO: Processing :84
0000006345 [lu] INFO: Processing :85
0000006397 [lu] INFO: Processing :86
0000006449 [lu] INFO: Processing :87
0000006501 [lu] INFO: Processing :88
0000006553 [lu] INFO: Processing :89
0000006605 [lu] INFO: Processing :90
0000006657 [lu] INFO: Processing :91
0000006709 [lu] INFO: Processing :92
0000006761 [lu] INFO: Processing :93
0000006813 [lu] INFO: Processing :94
0000006865 [lu] INFO: Processing :95
0000006917 [lu] INFO: Processing :96
0000006969 [lu] INFO: Processing :97
0000007021 [lu] INFO: Processing :98
0000007073 [lu] INFO: Processing :99
0000007125 [lu] INFO: Processing :100
0000007178 [lu] INFO: Processing :101
0000007229 [lu] INFO: Processing :102
0000007281 [lu] INFO: Processing :103
0000007333 [lu] INFO: Processing :104
0000007385 [lu] INFO: Processing :105
0000007437 [lu] INFO: Processing :106
0000007489 [lu] INFO: Processing :107
0000007541 [lu] INFO: Processing :108
0000007593 [lu] INFO: Processing :109
0000007645 [lu] INFO: Processing :110
0000007697 [lu] INFO: Processing :111
0000007749 [lu] INFO: Processing :112
0000007801 [lu] INFO: Processing :113
0000007853 [lu] INFO: Processing :114
0000007905 [lu] INFO: Processing :115
0000007906 [lu] INFO: Processing :116
0000007958 [lu] INFO: Processing :117
0000008010 [lu] INFO: Processing :118
0000008011 [lu] INFO: Processing :119
0000008063 [lu] INFO: Processing :120
0000008115 [lu] INFO: Processing :121
0000008167 [lu] INFO: Processing :122
0000008219 [lu] INFO: Processing :123
0000008220 [lu] INFO: Processing :124
0000008272 [lu] INFO: Processing :125
0000008324 [lu] INFO: Processing :126
0000008325 [lu] INFO: I2C devices at addr [19][36][38][40][41][44][45][50][51][74][77][7c]
0000008329 [lu] INFO: Finished scanning I2C bus
0000008340 [lu] INFO: Done Setup

Code with single_threaded_block

0000000272 [lu] INFO: Scanning I2C bus
0000000275 [lu] INFO: Processing :1
0000000277 [lu] INFO: Processing :2
0000000280 [lu] INFO: Processing :3
0000000288 [lu] INFO: Processing :4
0000000290 [lu] INFO: Processing :5
0000000297 [lu] INFO: Processing :6
0000000310 [lu] INFO: Processing :7
0000000313 [lu] INFO: Processing :8
0000000319 [lu] INFO: Processing :9
0000000321 [lu] INFO: Processing :10
0000000332 [lu] INFO: Processing :11
0000000335 [lu] INFO: Processing :12
0000000341 [lu] INFO: Processing :13
0000000355 [lu] INFO: Processing :14
0000000357 [lu] INFO: Processing :15
0000000364 [lu] INFO: Processing :16
0000000366 [lu] INFO: Processing :17
0000000377 [lu] INFO: Processing :18
0000000379 [lu] INFO: Processing :19
0000000386 [lu] INFO: Processing :20
0000000399 [lu] INFO: Processing :21
0000000402 [lu] INFO: Processing :22
0000000408 [lu] INFO: Processing :23
0000000421 [lu] INFO: Processing :24
0000000422 [lu] INFO: Processing :25
0000000430 [lu] INFO: Processing :26
0000000433 [lu] INFO: Processing :27
0000000444 [lu] INFO: Processing :28
0000000446 [lu] INFO: Processing :29
0000000453 [lu] INFO: Processing :30
0000000466 [lu] INFO: Processing :31
0000000468 [lu] INFO: Processing :32
0000000475 [lu] INFO: Processing :33
0000000488 [lu] INFO: Processing :34
0000000490 [lu] INFO: Processing :35
0000000497 [lu] INFO: Processing :36
0000000499 [lu] INFO: Processing :37
0000000510 [lu] INFO: Processing :38
0000000513 [lu] INFO: Processing :39
0000000519 [lu] INFO: Processing :40
0000000533 [lu] INFO: Processing :41
0000000535 [lu] INFO: Processing :42
0000000541 [lu] INFO: Processing :43
0000000555 [lu] INFO: Processing :44
0000000557 [lu] INFO: Processing :45
0000000560 [lu] INFO: Processing :46
0000000564 [lu] INFO: Processing :47
0000000577 [lu] INFO: Processing :48
0000000580 [lu] INFO: Processing :49
0000000586 [lu] INFO: Processing :50
0000000599 [lu] INFO: Processing :51
0000000602 [lu] INFO: Processing :52
0000000608 [lu] INFO: Processing :53
0000000609 [lu] INFO: Processing :54
0000000622 [lu] INFO: Processing :55
0000000622 [lu] INFO: Processing :56
0000000631 [lu] INFO: Processing :57
0000000644 [lu] INFO: Processing :58
0000000646 [lu] INFO: Processing :59
0000000653 [lu] INFO: Processing :60
0000000666 [lu] INFO: Processing :61
0000000668 [lu] INFO: Processing :62
0000000675 [lu] INFO: Processing :63
0000000675 [lu] INFO: Processing :64
0000000687 [lu] INFO: Processing :65
0000000689 [lu] INFO: Processing :66
0000000697 [lu] INFO: Processing :67
0000000709 [lu] INFO: Processing :68
0000000709 [lu] INFO: Processing :69
0000000719 [lu] INFO: Processing :70
0000000733 [lu] INFO: Processing :71
0000000735 [lu] INFO: Processing :72
0000000741 [lu] INFO: Processing :73
0000000744 [lu] INFO: Processing :74
0000000755 [lu] INFO: Processing :75
0000000757 [lu] INFO: Processing :76
0000000764 [lu] INFO: Processing :77
0000000777 [lu] INFO: Processing :78
0000000780 [lu] INFO: Processing :79
0000000784 [lu] INFO: Processing :80
0000000785 [lu] INFO: Processing :81
0000000800 [lu] INFO: Processing :82
0000000802 [lu] INFO: Processing :83
0000000809 [lu] INFO: Processing :84
0000000822 [lu] INFO: Processing :85
0000000824 [lu] INFO: Processing :86
0000000831 [lu] INFO: Processing :87
0000000844 [lu] INFO: Processing :88
0000000846 [lu] INFO: Processing :89
0000000853 [lu] INFO: Processing :90
0000000855 [lu] INFO: Processing :91
0000000866 [lu] INFO: Processing :92
0000000869 [lu] INFO: Processing :93
0000000875 [lu] INFO: Processing :94
0000000888 [lu] INFO: Processing :95
0000000891 [lu] INFO: Processing :96
0000000897 [lu] INFO: Processing :97
0000000911 [lu] INFO: Processing :98
0000000913 [lu] INFO: Processing :99
0000000919 [lu] INFO: Processing :100
0000000922 [lu] INFO: Processing :101
0000000933 [lu] INFO: Processing :102
0000000935 [lu] INFO: Processing :103
0000000942 [lu] INFO: Processing :104
0000000955 [lu] INFO: Processing :105
0000000958 [lu] INFO: Processing :106
0000000964 [lu] INFO: Processing :107
0000000977 [lu] INFO: Processing :108
0000000980 [lu] INFO: Processing :109
0000000986 [lu] INFO: Processing :110
0000000989 [lu] INFO: Processing :111
0000001000 [lu] INFO: Processing :112
0000001002 [lu] INFO: Processing :113
0000001009 [lu] INFO: Processing :114
0000001022 [lu] INFO: Processing :115
0000001022 [lu] INFO: Processing :116
0000001031 [lu] INFO: Processing :117
0000001044 [lu] INFO: Processing :118
0000001045 [lu] INFO: Processing :119
0000001053 [lu] INFO: Processing :120
0000001066 [lu] INFO: Processing :121
0000001069 [lu] INFO: Processing :122
0000001075 [lu] INFO: Processing :123
0000001076 [lu] INFO: Processing :124
0000001089 [lu] INFO: Processing :125
0000001091 [lu] INFO: Processing :126
0000001097 [lu] INFO: I2C devices at addr [19][36][38][40][41][44][45][50][51][74][77][7c]
0000001109 [lu] INFO: Finished scanning I2C bus
0000001118 [lu] INFO: Done Setup
0000002302 [ncp.at] TRACE: > AT
0000002303 [ncp.at] TRACE: < OK
0000003303 [hal] TRACE: NCP ready to accept AT commands
0000003303 [ncp.at] TRACE: > AT+CMUX=0
0000003305 [ncp.at] TRACE: < OK
0000003307 [gsm0710muxer] INFO: Starting GSM07.10 muxer
0000003329 [gsm0710muxer] INFO: Openning mux channel 0
0000003330 [gsm0710muxer] INFO: GSM07.10 muxer thread started
0000003402 [gsm0710muxer] INFO: Resuming channel 0
0000003402 [gsm0710muxer] INFO: Openning mux channel 1
0000003503 [gsm0710muxer] INFO: Resuming channel 1
0000003503 [gsm0710muxer] INFO: Resuming channel 1
0000003505 [ncp.at] TRACE: > AT
0000003556 [ncp.at] TRACE: < OK
0000003557 [ncp.at] TRACE: > AT+CWDHCP=0,3
0000003606 [ncp.at] TRACE: < OK
0000003606 [hal] TRACE: NCP state changed: 1
0000003607 [net.esp32ncp] TRACE: NCP event 1
0000003607 [ncp.at] TRACE: > AT+GETMAC=0
0000003656 [ncp.at] TRACE: < +GETMAC: "30:ae:a4:d1:f7:cc"
0000003656 [ncp.at] TRACE: < OK
0000003657 [gsm0710muxer] INFO: Stopping GSM07.10 muxer
0000003676 [gsm0710muxer] INFO: Gracefully stopping GSM07.10 muxer
0000003677 [gsm0710muxer] INFO: Closing all muxed channels
0000003699 [gsm0710muxer] INFO: Closing mux channel 1
0000003699 [gsm0710muxer] INFO: Muxed channel 2 already closed
0000003721 [gsm0710muxer] INFO: Muxed channel 3 already closed
0000003721 [gsm0710muxer] INFO: Muxed channel 4 already closed
0000003843 [gsm0710muxer] INFO: Sending CLD (multiplexer close down)
0000003893 [gsm0710muxer] INFO: Received response to CLD or timed out, exiting multiplexed mode
0000003893 [gsm0710muxer] INFO: GSM07.10 muxer thread exiting
0000003902 [gsm0710muxer] INFO: GSM07.10 muxer stopped
0000003920 [hal] TRACE: NCP state changed: 0
0000003920 [net.esp32ncp] TRACE: NCP event 1

armor · May 15, 2020, 1:03pm

What do you define as ‘boot’ - completing setup()? You seem to be doing an I2C bus scan in setup()?

ctmorrison · May 15, 2020, 1:34pm

My experience has been similar. From the time power is applied (or a reset), it takes far longer to get to breathing cyan mode. In my case, I’ve noticed this on an Argon, but haven’t really had the opportunity to view this on other model.

system · November 14, 2020, 1:34am

This topic was automatically closed 182 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
Strange behavior with firmware start-up Firmware	10	2356	August 23, 2015
Argon breathing white Firmware argon	7	888	March 29, 2019
[Particle Core] - I2C boot loop Troubleshooting	10	1609	December 10, 2017
I2C Timing off in 2.0.1 compared to 1.5.2. Debugging I2C Firmware boron	5	409	August 3, 2021
Smallest program causes reset after 50-60 Seconds Hardware argon	4	483	October 5, 2020

Firmware 151 takes 9seconds to boot verses 150 3seconds

Related Topics