Additional debug logging

everestjs/everestjs.cpp

@@ -556,6 +556,8 @@ static Napi::Value is_condition_satisfied_req(const Requirement& req, const Napi
 static Napi::Value boot_module(const Napi::CallbackInfo& info) {
     BOOST_LOG_FUNCTION();
 
+    const auto start_time = std::chrono::system_clock::now();
+
     auto env = info.Env();
 
     auto available_handlers_prop = Napi::Object::New(env);
@@ -946,6 +948,10 @@ static Napi::Value boot_module(const Napi::CallbackInfo& info) {
         ctx->js_cb = std::make_unique<JsExecCtx>(env, callback_wrapper);
         ctx->everest->register_on_ready_handler(framework_ready_handler);
 
+        const auto end_time = std::chrono::system_clock::now();
+        EVLOG_info << "Module " << fmt::format(Everest::TERMINAL_STYLE_BLUE, "{}", module_id) << " initialized ["
+                   << std::chrono::duration_cast<std::chrono::milliseconds>(end_time - start_time).count() << "ms]";
+
         ctx->everest->spawn_main_loop_thread();
 
     } catch (std::exception& e) {

everestpy/src/everest/module.cpp

@@ -21,7 +21,7 @@ Module::Module(const RuntimeSession& session) : Module(get_variable_from_env("EV
 }
 
 Module::Module(const std::string& module_id_, const RuntimeSession& session_) :
-    module_id(module_id_), session(session_) {
+    module_id(module_id_), session(session_), start_time(std::chrono::system_clock::now()) {
 
     this->mqtt_abstraction = std::make_shared<Everest::MQTTAbstraction>(session.get_mqtt_settings());
     this->mqtt_abstraction->connect();

everestpy/src/everest/module.hpp

@@ -3,6 +3,7 @@
 #ifndef EVERESTPY_MODULE_HPP
 #define EVERESTPY_MODULE_HPP
 
+#include <chrono>
 #include <deque>
 #include <functional>
 #include <map>
@@ -28,6 +29,11 @@ class Module {
             handle->register_on_ready_handler(on_ready_handler);
         }
 
+        const auto end_time = std::chrono::system_clock::now();
+        EVLOG_info << "Module " << fmt::format(Everest::TERMINAL_STYLE_BLUE, "{}", this->module_id) << " initialized ["
+                   << std::chrono::duration_cast<std::chrono::milliseconds>(end_time - this->start_time).count()
+                   << "ms]";
+
         handle->signal_ready();
     }
 
@@ -78,6 +84,7 @@ class Module {
 private:
     const std::string module_id;
     const RuntimeSession& session;
+    const std::chrono::time_point<std::chrono::system_clock> start_time;
     std::unique_ptr<Everest::RuntimeSettings> rs;
     std::shared_ptr<Everest::MQTTAbstraction> mqtt_abstraction;
     std::unique_ptr<Everest::Config> config_;

src/manager.cpp

@@ -300,8 +300,9 @@ static std::map<pid_t, std::string> start_modules(ManagerConfig& config, MQTTAbs
 
     std::vector<ModuleStartInfo> modules_to_spawn;
 
-    const auto main_config = config.get_main_config();
-    modules_to_spawn.reserve(main_config.size());
+    const auto& main_config = config.get_main_config();
+    const auto number_of_modules = main_config.size();
+    EVLOG_info << "Starting " << number_of_modules << " modules";
 
     const auto serialized_config = config.serialize();
     const auto interface_definitions = config.get_interface_definitions();