Optimize log message code generation (celeritas-project#1101)

* Force-inline logger message functions
* Pass provenance by rvalue
* Use string view for provenance
* Only inline non-null log message components
* Mark logging as unlikely
* Fix potential bug when moving logger message
* Remove silly dynamic cast
* Rename Provenance to LogProvenance

app/celer-g4/LocalLogger.cc

@@ -20,7 +20,7 @@ namespace app
 /*!
  * Write a log message.
  */
-void LocalLogger::operator()(Provenance prov, LogLevel lev, std::string msg)
+void LocalLogger::operator()(LogProvenance prov, LogLevel lev, std::string msg)
 {
     // Write preamble to a buffer first
     std::ostringstream os;

app/celer-g4/LocalLogger.hh

@@ -30,7 +30,7 @@ class LocalLogger
     }
 
     // Write a log message
-    void operator()(Provenance prov, LogLevel lev, std::string msg);
+    void operator()(LogProvenance prov, LogLevel lev, std::string msg);
 
   private:
     int num_threads_;

src/accel/Logger.cc

@@ -35,7 +35,7 @@ class MtLogger
 {
   public:
     explicit MtLogger(int num_threads);
-    void operator()(Provenance prov, LogLevel lev, std::string msg);
+    void operator()(LogProvenance prov, LogLevel lev, std::string msg);
 
   private:
     int num_threads_;
@@ -48,7 +48,7 @@ MtLogger::MtLogger(int num_threads) : num_threads_(num_threads)
 }
 
 //---------------------------------------------------------------------------//
-void MtLogger::operator()(Provenance prov, LogLevel lev, std::string msg)
+void MtLogger::operator()(LogProvenance prov, LogLevel lev, std::string msg)
 {
     auto& cerr = G4cerr;
 

src/corecel/io/Logger.cc

@@ -31,7 +31,7 @@ namespace
 // HELPER CLASSES
 //---------------------------------------------------------------------------//
 //! Default global logger prints the error message with basic colors
-void default_global_handler(Provenance prov, LogLevel lev, std::string msg)
+void default_global_handler(LogProvenance prov, LogLevel lev, std::string msg)
 {
     static std::mutex log_mutex;
     std::lock_guard<std::mutex> scoped_lock{log_mutex};
@@ -57,7 +57,7 @@ class LocalHandler
   public:
     explicit LocalHandler(MpiCommunicator const& comm) : rank_(comm.rank()) {}
 
-    void operator()(Provenance prov, LogLevel lev, std::string msg)
+    void operator()(LogProvenance prov, LogLevel lev, std::string msg)
     {
         // Use buffered 'clog'
         std::clog << color_code('x') << prov.file << ':' << prov.line

src/corecel/io/Logger.hh

@@ -17,10 +17,10 @@
 // MACROS
 //---------------------------------------------------------------------------//
 //! Inject the source code provenance (current file and line)
-#define CELER_CODE_PROVENANCE \
-    ::celeritas::Provenance   \
-    {                         \
-        __FILE__, __LINE__    \
+#define CELER_CODE_PROVENANCE  \
+    ::celeritas::LogProvenance \
+    {                          \
+        __FILE__, __LINE__     \
     }
 
 /*!
@@ -90,7 +90,7 @@ class Logger
     Logger(MpiCommunicator const& comm, LogHandler handle);
 
     // Create a logger that flushes its contents when it destructs
-    inline Message operator()(Provenance prov, LogLevel lev);
+    inline Message operator()(LogProvenance&& prov, LogLevel lev);
 
     //! Set the minimum logging verbosity
     void level(LogLevel lev) { min_level_ = lev; }
@@ -106,11 +106,17 @@ class Logger
 //---------------------------------------------------------------------------//
 // INLINE DEFINITIONS
 //---------------------------------------------------------------------------//
-//! Create a logger that flushes its contents when it destructs
-auto Logger::operator()(Provenance prov, LogLevel lev) -> Message
+/*!
+ * Create a logger that flushes its contents when it destructs.
+ *
+ * It's assumed that log messages will be relatively unlikely (and expensive
+ * anyway), so we mark as \c CELER_UNLIKELY to optimize for the no-logging
+ * case.
+ */
+auto Logger::operator()(LogProvenance&& prov, LogLevel lev) -> Message
 {
     LogHandler* handle = nullptr;
-    if (handle_ && lev >= min_level_)
+    if (CELER_UNLIKELY(handle_ && lev >= min_level_))
     {
         handle = &handle_;
     }

src/corecel/io/LoggerTypes.hh

@@ -8,8 +8,9 @@
 //---------------------------------------------------------------------------//
 #pragma once
 
+#include <cstdlib>  // IWYU pragma: keep
 #include <functional>
-#include <string>
+#include <string_view>
 
 namespace celeritas
 {
@@ -39,14 +40,17 @@ char const* to_color_code(LogLevel);
 
 //---------------------------------------------------------------------------//
 //! Stand-in for a more complex class for the "provenance" of data
-struct Provenance
+struct LogProvenance
 {
-    std::string file;  //!< Originating file
-    int line = 0;  //!< Line number
+    std::string_view file;  //!< Originating file
+    int line{0};  //!< Line number
 };
 
 //! Type for handling a log message
-using LogHandler = std::function<void(Provenance, LogLevel, std::string)>;
+using LogHandler = std::function<void(LogProvenance, LogLevel, std::string)>;
+
+// DEPRECATED: remove in v0.6
+using Provenance [[deprecated]] = LogProvenance;
 
 //---------------------------------------------------------------------------//
 }  // namespace celeritas

src/corecel/io/detail/LoggerMessage.cc

@@ -9,6 +9,7 @@
 
 #include <exception>
 #include <functional>
+#include <iostream>
 #include <sstream>
 
 #include "corecel/Assert.hh"
@@ -21,44 +22,36 @@ namespace detail
 {
 //---------------------------------------------------------------------------//
 /*!
- * Construct with reference to function object, etc.
+ * Create the message when handle is non-null.
  *
- * The handle *may be* null, indicating that the output of this message will
- * not be displayed.
+ * This saves the provided data and allocates a stream for output.
  */
-LoggerMessage::LoggerMessage(LogHandler* handle, Provenance prov, LogLevel lev)
-    : handle_(handle), prov_(prov), lev_(lev)
+void LoggerMessage::construct_impl(LogProvenance&& prov, LogLevel lev)
 {
-    CELER_EXPECT(!handle_ || *handle_);
-    if (handle_)
-    {
-        // std::function is defined, so create the output stream
-        os_ = std::make_unique<std::ostringstream>();
-    }
-    CELER_ENSURE(bool(handle_) == bool(os_));
+    CELER_EXPECT(handle_ && *handle_);
+
+    prov_ = std::move(prov);
+    lev_ = lev;
+    os_ = std::make_unique<std::ostringstream>();
 }
 
 //---------------------------------------------------------------------------//
 /*!
  * Flush message on destruction.
+ *
+ * This is only called when \c os_ is nonnull.
  */
-LoggerMessage::~LoggerMessage()
+void LoggerMessage::destroy_impl() noexcept
 {
-    if (os_)
+    try
     {
-        try
-        {
-            auto& os = dynamic_cast<std::ostringstream&>(*os_);
-
-            // Write to the handler
-            (*handle_)(prov_, lev_, os.str());
-        }
-        catch (std::exception const& e)
-        {
-            std::cerr
-                << "An error occurred writing a log message: " << e.what()
-                << std::endl;
-        }
+        // Write to the handler
+        (*handle_)(prov_, lev_, os_->str());
+    }
+    catch (std::exception const& e)
+    {
+        std::cerr << "An error occurred writing a log message: " << e.what()
+                  << std::endl;
     }
 }
 

src/corecel/io/detail/LoggerMessage.hh

@@ -7,10 +7,12 @@
 //---------------------------------------------------------------------------//
 #pragma once
 
-#include <iostream>
 #include <memory>
+#include <sstream>
 #include <utility>
 
+#include "corecel/Macros.hh"
+
 #include "../LoggerTypes.hh"
 
 namespace celeritas
@@ -34,10 +36,10 @@ class LoggerMessage
 
   public:
     // Construct with reference to function object, etc.
-    LoggerMessage(LogHandler* handle, Provenance prov, LogLevel lev);
+    inline LoggerMessage(LogHandler* handle, LogProvenance&& prov, LogLevel lev);
 
     // Flush message on destruction
-    ~LoggerMessage();
+    inline ~LoggerMessage();
 
     //!@{
     //! Prevent copying but allow moving
@@ -54,24 +56,63 @@ class LoggerMessage
     // Accept manipulators such as std::endl, std::setw
     inline LoggerMessage& operator<<(StreamManip manip);
 
-    // Update the steam state
+    // Update the stream state
     inline void setstate(std::ostream::iostate state);
 
   private:
     LogHandler* handle_;
-    Provenance prov_;
+    LogProvenance prov_;
     LogLevel lev_;
-    std::unique_ptr<std::ostream> os_;
+    std::unique_ptr<std::ostringstream> os_;
+
+    // Create the message when handle is non-null
+    void construct_impl(LogProvenance&& prov, LogLevel lev);
+
+    // Flush the message during destruction
+    void destroy_impl() noexcept;
 };
 
+//---------------------------------------------------------------------------//
+/*!
+ * Construct with reference to function object, etc.
+ *
+ * The handle *may be* null, indicating that the output of this message will
+ * not be displayed.
+ */
+CELER_FORCEINLINE LoggerMessage::LoggerMessage(LogHandler* handle,
+                                               LogProvenance&& prov,
+                                               LogLevel lev)
+    : handle_(handle)
+{
+    if (CELER_UNLIKELY(handle_))
+    {
+        this->construct_impl(std::move(prov), lev);
+    }
+}
+
+//---------------------------------------------------------------------------//
+/*!
+ * Flush message on destruction.
+ *
+ * Note that due to move semantics, it's possible for a stale "moved"
+ * LoggerMessage to have a nonnull \c handle_ but a null \c os_ .
+ */
+CELER_FORCEINLINE LoggerMessage::~LoggerMessage()
+{
+    if (CELER_UNLIKELY(os_))
+    {
+        this->destroy_impl();
+    }
+}
+
 //---------------------------------------------------------------------------//
 /*!
  * Write the object to the stream if applicable.
  */
 template<class T>
-LoggerMessage& LoggerMessage::operator<<(T&& rhs)
+CELER_FORCEINLINE LoggerMessage& LoggerMessage::operator<<(T&& rhs)
 {
-    if (os_)
+    if (CELER_UNLIKELY(os_))
     {
         *os_ << std::forward<T>(rhs);
     }
@@ -82,9 +123,9 @@ LoggerMessage& LoggerMessage::operator<<(T&& rhs)
 /*!
  * Accept a stream manipulator.
  */
-LoggerMessage& LoggerMessage::operator<<(StreamManip manip)
+CELER_FORCEINLINE LoggerMessage& LoggerMessage::operator<<(StreamManip manip)
 {
-    if (os_)
+    if (CELER_UNLIKELY(os_))
     {
         manip(*os_);
     }
@@ -95,9 +136,9 @@ LoggerMessage& LoggerMessage::operator<<(StreamManip manip)
 /*!
  * Update the steam state (needed by some manipulators).
  */
-void LoggerMessage::setstate(std::ostream::iostate state)
+CELER_FORCEINLINE void LoggerMessage::setstate(std::ostream::iostate state)
 {
-    if (os_)
+    if (CELER_UNLIKELY(os_))
     {
         os_->setstate(state);
     }

test/corecel/ScopedLogStorer.cc

@@ -56,7 +56,7 @@ ScopedLogStorer::~ScopedLogStorer()
 
 //---------------------------------------------------------------------------//
 //! Save a log message
-void ScopedLogStorer::operator()(Provenance, LogLevel lev, std::string msg)
+void ScopedLogStorer::operator()(LogProvenance, LogLevel lev, std::string msg)
 {
     static std::regex const delete_ansi("\033\\[[0-9;]*m");
     static std::regex const subs_ptr("0x[0-9a-f]+");

test/corecel/ScopedLogStorer.hh

@@ -60,7 +60,7 @@ class ScopedLogStorer
     ~ScopedLogStorer();
 
     // Save a log message
-    void operator()(Provenance, LogLevel lev, std::string msg);
+    void operator()(LogProvenance, LogLevel lev, std::string msg);
 
     //! Whether no messages were stored
     bool empty() const { return messages_.empty(); }

test/corecel/io/Logger.test.cc

@@ -88,15 +88,16 @@ TEST_F(LoggerTest, null)
 
 TEST_F(LoggerTest, custom_log)
 {
-    Provenance last_prov;
+    LogProvenance last_prov;
     LogLevel last_lev = LogLevel::debug;
     std::string last_msg;
 
-    Logger log(comm_self, [&](Provenance prov, LogLevel lev, std::string msg) {
-        last_prov = prov;
-        last_lev = lev;
-        last_msg = std::move(msg);
-    });
+    Logger log(comm_self,
+               [&](LogProvenance prov, LogLevel lev, std::string msg) {
+                   last_prov = prov;
+                   last_lev = lev;
+                   last_msg = std::move(msg);
+               });
 
     // Update level
     EXPECT_EQ(LogLevel::status, log.level());
@@ -131,9 +132,11 @@ TEST_F(LoggerTest, DISABLED_performance)
 {
     // Construct a logger with an expensive output routine that will never be
     // called
-    Logger log(comm_self, [&](Provenance prov, LogLevel lev, std::string msg) {
-        cout << prov.file << prov.line << static_cast<int>(lev) << msg << endl;
-    });
+    Logger log(comm_self,
+               [&](LogProvenance prov, LogLevel lev, std::string msg) {
+                   cout << prov.file << prov.line << static_cast<int>(lev)
+                        << msg << endl;
+               });
     log.level(LogLevel::critical);
 
     // Even in debug this takes only 26ms