Merge pull request #2521 from STEllAR-GROUP/logging_progress

Create LPROGRESS_ logging macro to simplify progress tracking and timings

docs/manual/commandline.qbk

@@ -122,6 +122,9 @@ described in the table below:
                                        log channel and send all parcel transport
                                        logs to the target destination (default:
                                        cout)]]
+    [[`--hpx:debug-timing-log [arg]`] [enable all messages on the timing log
+                                       channel and send all timing logs to the
+                                       target destination (default: cout)]]
     [[`--hpx:debug-clp`]        [debug command line processing]]
     [[`--hpx:attach-debugger arg`] [wait for a debugger to be attached, possible arg values:
                                     `startup` or `exception` (default: startup)]]

hpx/runtime.hpp

@@ -373,7 +373,7 @@ namespace hpx
         void deinit_tss();
 
     public:
-        void set_state(state s) { state_.store(s); }
+        void set_state(state s);
 
     protected:
         util::reinit_helper reinit_;

hpx/runtime_impl.hpp

@@ -21,7 +21,6 @@
 #include <hpx/runtime/threads/threadmanager.hpp>
 #include <hpx/runtime/threads/topology.hpp>
 #include <hpx/util/generate_unique_ids.hpp>
-#include <hpx/util/init_logging.hpp>
 #include <hpx/util/io_service_pool.hpp>
 #include <hpx/util/thread_specific_ptr.hpp>
 #include <hpx/util_fwd.hpp>
@@ -386,7 +385,6 @@ namespace hpx
         boost::scoped_ptr<hpx::threads::threadmanager_base> thread_manager_;
         parcelset::parcelhandler parcel_handler_;
         naming::resolver_client agas_client_;
-        util::detail::init_logging init_logging_;
         applier::applier applier_;
         boost::signals2::scoped_connection default_error_sink_;
 

hpx/util/block_profiler.hpp

@@ -1,4 +1,4 @@
-//  Copyright (c) 2007-2012 Hartmut Kaiser
+//  Copyright (c) 2007-2017 Hartmut Kaiser
 //
 //  Distributed under the Boost Software License, Version 1.0. (See accompanying
 //  file LICENSE_1_0.txt or copy at http://www.boost.org/LICENSE_1_0.txt)
@@ -58,7 +58,7 @@ namespace hpx { namespace util
 
             void print_stats()
             {
-                LTIM_(fatal) << "profiler: " << description_ << ": "
+                LTIM_(error) << "profiler: " << description_ << ": "
                             << boost::accumulators::sum(totals_) << " ("
                             << boost::accumulators::count(totals_) << ", "
                             << boost::accumulators::mean(totals_) << ", "
@@ -126,7 +126,7 @@ namespace hpx { namespace util
 
             void print_stats()
             {
-                LTIM_(fatal) << "profiler: " << description_ << ": "
+                LTIM_(error) << "profiler: " << description_ << ": "
                             << extract_count(totals_) << ", "
                             << extract_mean(totals_);
             }
@@ -214,13 +214,13 @@ namespace hpx { namespace util
         // special interface for block_profiler_wrapper below
         void measure(double started)
         {
-            if (enable_logging_ && LTIM_ENABLED(fatal))
+            if (enable_logging_ && LTIM_ENABLED(error))
                 stats_.add(started);
         }
 
         double elapsed()
         {
-            return enable_logging_ && LTIM_ENABLED(fatal) ? stats_.elapsed() : 0;
+            return enable_logging_ && LTIM_ENABLED(error) ? stats_.elapsed() : 0;
         }
 
     private:

hpx/util/init_logging.hpp

@@ -1,12 +1,11 @@
-//  Copyright (c) 2007-2013 Hartmut Kaiser
+//  Copyright (c) 2007-2017 Hartmut Kaiser
 //
 //  Distributed under the Boost Software License, Version 1.0. (See accompanying
 //  file LICENSE_1_0.txt or copy at http://www.boost.org/LICENSE_1_0.txt)
 
 #if !defined(HPX_UTIL_AGAS_INIT_LOGGING_SEP_07_2013_0754PM)
 #define HPX_UTIL_AGAS_INIT_LOGGING_SEP_07_2013_0754PM
 
-#include <hpx/runtime/agas_fwd.hpp>
 #include <hpx/runtime_fwd.hpp>
 #include <hpx/util/ini.hpp>
 #include <hpx/util_fwd.hpp>
@@ -18,11 +17,7 @@ namespace hpx { namespace util { namespace detail
 {
     // the init_logging type will be used for initialization purposes only as
     // well
-    struct init_logging
-    {
-        init_logging(runtime_configuration& ini, bool isconsole,
-            agas::addressing_service& agas_client);
-    };
+    HPX_API_EXPORT void init_logging(runtime_configuration& ini, bool isconsole);
 }}}
 
 #endif

hpx/util/logging.hpp

@@ -1,4 +1,4 @@
-//  Copyright (c) 2007-2013 Hartmut Kaiser
+//  Copyright (c) 2007-2017 Hartmut Kaiser
 //
 //  Distributed under the Boost Software License, Version 1.0. (See accompanying
 //  file LICENSE_1_0.txt or copy at http://www.boost.org/LICENSE_1_0.txt)
@@ -16,8 +16,22 @@
 #include <hpx/util/logging/format/named_write.hpp>
 #include <hpx/util/logging/format_fwd.hpp>
 
+#include <boost/current_function.hpp>
+
 HPX_LOG_FORMAT_MSG(optimize::cache_string_one_str<>)
 
+///////////////////////////////////////////////////////////////////////////////
+// specific logging
+#define LTM_(lvl)   LHPX_(lvl, "  [TM] ")   /* thread manager */
+#define LRT_(lvl)   LHPX_(lvl, "  [RT] ")   /* runtime support */
+#define LOSH_(lvl)  LHPX_(lvl, " [OSH] ")   /* one size heap */
+#define LERR_(lvl)  LHPX_(lvl, " [ERR] ")   /* exceptions */
+#define LLCO_(lvl)  LHPX_(lvl, " [LCO] ")   /* lcos */
+#define LPCS_(lvl)  LHPX_(lvl, " [PCS] ")   /* performance counters */
+#define LAS_(lvl)   LHPX_(lvl, "  [AS] ")   /* addressing service */
+#define LBT_(lvl)   LHPX_(lvl, "  [BT] ")   /* bootstrap */
+#define LSEC_(lvl)  LHPX_(lvl, " [SEC] ")   /* security */
+
 ///////////////////////////////////////////////////////////////////////////////
 namespace hpx { namespace util
 {
@@ -65,6 +79,11 @@ namespace hpx { namespace util
             hpx::util::timing_level(), lvl)                                   \
         << hpx::util::levelname(::hpx::util::logging::level::lvl) << " "      \
     /**/
+    #define LPROGRESS_                                                        \
+        HPX_LOG_USE_LOG_IF_LEVEL(hpx::util::timing_logger(),                  \
+            hpx::util::timing_level(), fatal) << " "                          \
+        << __FILE__ << ":" << __LINE__ << " " << BOOST_CURRENT_FUNCTION << " "\
+    /**/
 
     #define LTIM_ENABLED(lvl)                                                 \
         hpx::util::timing_level()->is_enabled(::hpx::util::logging::level::lvl)\
@@ -209,6 +228,19 @@ namespace hpx { namespace util
             hpx::util::logging::level::error))                                \
 /**/
 
+// helper type to forward logging during bootstrap to two destinations
+struct bootstrap_logging { constexpr bootstrap_logging() {} };
+
+template <typename T>
+bootstrap_logging const& operator<< (bootstrap_logging const& l, T const& t)
+{
+    LBT_(info) << t;
+    LPROGRESS_ << t;
+    return l;
+}
+
+constexpr bootstrap_logging lbt_;
+
 #else
 // logging is disabled all together
 
@@ -219,15 +251,28 @@ namespace hpx { namespace util { namespace detail
     // with logging specific data
     HPX_EXPORT std::vector<std::string> get_logging_data();
 
-    struct dummy_log_impl {};
-    HPX_EXPORT extern dummy_log_impl dummy_log;
+    struct dummy_log_impl { constexpr dummy_log_impl() {} };
+    constexpr dummy_log_impl dummy_log;
 
     template <typename T>
-    inline dummy_log_impl& operator<<(dummy_log_impl& l, T&&) { return l; }
+    dummy_log_impl const& operator<<(dummy_log_impl const& l, T&&)
+    {
+        return l;
+    }
+
+    struct bootstrap_logging { constexpr bootstrap_logging() {} };
+    constexpr bootstrap_logging lbt_;
+
+    template <typename T>
+    bootstrap_logging const& operator<< (bootstrap_logging const& l, T&&)
+    {
+        return l;
+    }
 
     #define LAGAS_(lvl)           if(true) {} else hpx::util::detail::dummy_log
     #define LPT_(lvl)             if(true) {} else hpx::util::detail::dummy_log
     #define LTIM_(lvl)            if(true) {} else hpx::util::detail::dummy_log
+    #define LPROGRESS_            if(true) {} else hpx::util::detail::dummy_log
     #define LHPX_(lvl, cat)       if(true) {} else hpx::util::detail::dummy_log
     #define LAPP_(lvl)            if(true) {} else hpx::util::detail::dummy_log
     #define LDEB_                 if(true) {} else hpx::util::detail::dummy_log
@@ -250,19 +295,6 @@ namespace hpx { namespace util { namespace detail
 }}}
 
 #endif
-
-///////////////////////////////////////////////////////////////////////////////
-// specific logging
-#define LTM_(lvl)   LHPX_(lvl, "  [TM] ")   /* thread manager */
-#define LRT_(lvl)   LHPX_(lvl, "  [RT] ")   /* runtime support */
-#define LOSH_(lvl)  LHPX_(lvl, " [OSH] ")   /* one size heap */
-#define LERR_(lvl)  LHPX_(lvl, " [ERR] ")   /* exceptions */
-#define LLCO_(lvl)  LHPX_(lvl, " [LCO] ")   /* lcos */
-#define LPCS_(lvl)  LHPX_(lvl, " [PCS] ")   /* performance counters */
-#define LAS_(lvl)   LHPX_(lvl, "  [AS] ")   /* addressing service */
-#define LBT_(lvl)   LHPX_(lvl, "  [BT] ")   /* bootstrap */
-#define LSEC_(lvl)  LHPX_(lvl, " [SEC] ")   /* security */
-
 #endif
 
 

src/hpx_init.cpp

@@ -25,6 +25,8 @@
 #include <hpx/util/bind_action.hpp>
 #include <hpx/util/command_line_handling.hpp>
 #include <hpx/util/function.hpp>
+#include <hpx/util/init_logging.hpp>
+#include <hpx/util/logging.hpp>
 #include <hpx/util/query_counters.hpp>
 
 #include <boost/algorithm/string/split.hpp>
@@ -692,6 +694,8 @@ namespace hpx
             boost::program_options::variables_map& vm, runtime_mode mode,
             startup_function_type startup, shutdown_function_type shutdown)
         {
+            LPROGRESS_;
+
             add_startup_functions(rt, vm, mode, std::move(startup),
                 std::move(shutdown));
 
@@ -709,6 +713,8 @@ namespace hpx
             boost::program_options::variables_map& vm, runtime_mode mode,
             startup_function_type startup, shutdown_function_type shutdown)
         {
+            LPROGRESS_;
+
             add_startup_functions(rt, vm, mode, std::move(startup),
                 std::move(shutdown));
 
@@ -764,6 +770,8 @@ namespace hpx
             threads::policies::init_affinity_data affinity_init(
                 pu_offset, pu_step, affinity_domain, affinity_desc);
 
+            LPROGRESS_ << "run_local: create runtime";
+
             // Build and configure this runtime instance.
             typedef hpx::runtime_impl<local_queue_policy> runtime_type;
             std::unique_ptr<hpx::runtime> rt(
@@ -806,6 +814,8 @@ namespace hpx
             threads::policies::init_affinity_data affinity_init(
                 pu_offset, pu_step, affinity_domain, affinity_desc);
 
+            LPROGRESS_ << "run_throttle: create runtime";
+
             // Build and configure this runtime instance.
             typedef hpx::runtime_impl<throttle_queue_policy> runtime_type;
             std::unique_ptr<hpx::runtime> rt(
@@ -852,6 +862,8 @@ namespace hpx
             threads::policies::init_affinity_data affinity_init(
                 pu_offset, pu_step, affinity_domain, affinity_desc);
 
+            LPROGRESS_ << "run_static_priority: create runtime";
+
             // Build and configure this runtime instance.
             typedef hpx::runtime_impl<local_queue_policy> runtime_type;
             std::unique_ptr<hpx::runtime> rt(
@@ -896,6 +908,8 @@ namespace hpx
             threads::policies::init_affinity_data affinity_init(
                 pu_offset, pu_step, affinity_domain, affinity_desc);
 
+            LPROGRESS_ << "run_static: create runtime";
+
             // Build and configure this runtime instance.
             typedef hpx::runtime_impl<local_queue_policy> runtime_type;
             std::unique_ptr<hpx::runtime> rt(
@@ -942,6 +956,8 @@ namespace hpx
             threads::policies::init_affinity_data affinity_init(
                 pu_offset, pu_step, affinity_domain, affinity_desc);
 
+            LPROGRESS_ << "run_priority_local: create runtime";
+
             // Build and configure this runtime instance.
             typedef hpx::runtime_impl<local_queue_policy> runtime_type;
             std::unique_ptr<hpx::runtime> rt(
@@ -975,6 +991,8 @@ namespace hpx
                 cfg.num_threads_, num_high_priority_queues, 1000,
                 cfg.numa_sensitive_, "core-abp_fifo_priority_queue_scheduler");
 
+            LPROGRESS_ << "run_priority_abp: create runtime";
+
             // Build and configure this runtime instance.
             typedef hpx::runtime_impl<abp_priority_queue_policy> runtime_type;
             std::unique_ptr<hpx::runtime> rt(
@@ -1011,6 +1029,8 @@ namespace hpx
             queue_policy::init_parameter_type init(cfg.num_threads_, arity,
                 1000, 0, "core-hierarchy_scheduler");
 
+            LPROGRESS_ << "run_hierarchy: create runtime";
+
             // Build and configure this runtime instance.
             typedef hpx::runtime_impl<queue_policy> runtime_type;
             std::unique_ptr<hpx::runtime> rt(
@@ -1047,6 +1067,8 @@ namespace hpx
                 num_high_priority_queues, 1000, cfg.numa_sensitive_,
                 "core-periodic_priority_queue_scheduler");
 
+            LPROGRESS_ << "run_periodic: create runtime";
+
             // Build and configure this runtime instance.
             typedef hpx::runtime_impl<local_queue_policy> runtime_type;
             std::unique_ptr<hpx::runtime> rt(
@@ -1092,7 +1114,6 @@ namespace hpx
             unsetenv("LC_IDENTIFICATION");
             unsetenv("LC_ALL");
 #endif
-
             try {
                 // make sure the runtime system is not active yet
                 if (get_runtime_ptr() != nullptr)
@@ -1114,6 +1135,10 @@ namespace hpx
                     return result;
                 }
 
+                // initialize logging
+                util::detail::init_logging(cfg.rtcfg_,
+                    cfg.mode_ == runtime_mode_console);
+
                 util::apex_wrapper_init apex(argc, argv);
 
                 // Initialize and start the HPX runtime.