...
 
Commits (8)
  • Steffen Müthing's avatar
    [logging] Make sure sink pattern arguments live through the {fmt} call · e5284569
    Steffen Müthing authored
    The PatternFormatSink crashes in optimized builds because the arguments
    retrieved from the arguments() function are always invalid. This is due to two
    object lifetime problems:
    
    - fmt::format_args is only a view onto an externally allocated array of
      type-erased format arguments. We allocated this array in a temporary object of
      type fmt::format_arg_store in arguments(), but that became invalid as soon as
      that function ended.
    
    - The type-erased format arguments in fmt::format_arg_store only store
      references to existing data, which causes yet another problem, as some of the
      data that we want to provide is returned as temporary objects from the
      LogMessage etc.
    
    To work around this problem, we need to store both the data and an instance of
    fmt::format_arg_store for the duration of the {fmt} calls in a derived sink.
    This patch adds a new member type `Arguments` for this purpose. Arguments
    stores this data without exposing the details to the user (the object only
    contains two char* buffers for it), which keeps user code away from the code
    bloat of captured lambda functions et. al. Arguments **must** be stored as a
    named variable (to guarantee a sufficient lifetime) and implicitly casts into
    fmt::format_args if used that way.
    e5284569
  • Steffen Müthing's avatar
    [logging] Improve PatternFormatSink configuration · 183bd02f
    Steffen Müthing authored
    Use a regular member function instead of a static one, and explicitly put the
    name of the class into the function name in case there will be more mixins.
    183bd02f
  • Steffen Müthing's avatar
    Use localtime_r() if available · 0ddb9737
    Steffen Müthing authored
    That function is reentrant and also saves us one round of memcpy().
    0ddb9737
  • Steffen Müthing's avatar
    [doc] Fix typo · ca9bd55d
    Steffen Müthing authored
    ca9bd55d
  • Steffen Müthing's avatar
    f4a95950
  • Steffen Müthing's avatar
    Add DestructibleSingletonHolder utility · 2d6c17dd
    Steffen Müthing authored
    DestructibleSingletonHolder is a little utility that helps in building
    singletons that can be created and destroyed multiple times during the lifetime
    of a program. The class holds a unique_ptr to the actual singleton
    implementation and an instance of a factory for allocating that unique_ptr and
    initializing the singleton.
    
    The class is accompanied by a function template that stores an instance of the
    class in a static variable, which provides for the singleton. This function must
    always be called with the factory function, as it is templated on it. This makes
    it possible to keep the singleton private to a class by using a private static
    member function as the factory.
    2d6c17dd
  • Steffen Müthing's avatar
  • Steffen Müthing's avatar
    ff611e5b
......@@ -7,6 +7,9 @@ else()
find_package(fmt CONFIG)
endif()
include(CheckSymbolExists)
check_symbol_exists(localtime_r time.h DUNE_HAVE_LOCALTIME_R)
function(add_dune_petsc_flags)
if(PETSC_FOUND)
cmake_parse_arguments(ADD_PETSC "SOURCE_ONLY;OBJECT" "" "" ${ARGN})
......
......@@ -53,4 +53,7 @@
/* Define to 1 if sequential UG has been found */
#cmakedefine PDELAB_SEQUENTIAL_UG 1
/* Defined if localtime_r() is available */
#cmakedefine DUNE_HAVE_LOCALTIME_R 1
/* end dune-pdelab */
......@@ -7,6 +7,7 @@ install(FILES benchmarkhelper.hh
checks.hh
${clock_hh}
crossproduct.hh
destructiblesingletonholder.hh
dofindex.hh
elementmapper.hh
exceptions.hh
......
#ifndef DUNE_PDELAB_COMMON_DESTRUCTIBLESINGLETONHOLDER_HH
#define DUNE_PDELAB_COMMON_DESTRUCTIBLESINGLETONHOLDER_HH
#include <memory>
#include <dune/pdelab/common/exceptions.hh>
namespace Dune::PDELab {
template<typename Singleton, typename Factory>
class DestructibleSingletonHolder
{
std::unique_ptr<Singleton> _data;
Factory _factory;
public:
template<typename... T>
void create(T&... args)
{
if (_data)
DUNE_THROW(Exception,"Singleton already created");
_data = _factory(std::forward<T>(args)...);
}
operator bool() const
{
return bool(_data);
}
Singleton& get()
{
return *_data;
}
void destroy()
{
if (not _data)
DUNE_THROW(Exception,"Singleton not present");
_data.reset();
}
DestructibleSingletonHolder(Factory factory)
: _factory(std::move(factory))
{}
};
template<typename Singleton, typename Factory>
DestructibleSingletonHolder<Singleton,Factory>& destructibleSingleton(Factory factory)
{
static DestructibleSingletonHolder<Singleton,Factory> holder(std::move(factory));
return holder;
}
} // Dune::PDELab
#endif // DUNE_PDELAB_COMMON_DESTRUCTIBLESINGLETONHOLDER_HH
......@@ -13,6 +13,7 @@
#include <unordered_set>
#include <vector>
#include <dune/pdelab/common/destructiblesingletonholder.hh>
#include <dune/pdelab/common/utility.hh>
#include <dune/pdelab/logging.hh>
#include <dune/pdelab/logging/loggerbackend.hh>
......@@ -72,7 +73,7 @@ namespace Dune::PDELab {
auto sink = std::make_shared<FileSink>(name,level,widest_logger,file_name,mode);
PatternFormatSink::setParameters(*sink,params);
sink->setPatternFormatParameters(params);
return sink;
}
......@@ -109,7 +110,7 @@ namespace Dune::PDELab {
if (comm.rank() == 0)
{
auto sink = std::make_shared<FileSink>(name,level,widest_logger,file_name,mode);
PatternFormatSink::setParameters(*sink,params);
sink->setPatternFormatParameters(params);
return sink;
}
else
......@@ -187,6 +188,7 @@ namespace Dune::PDELab {
LogLevel unmuted_cerr = LogLevel::all;
std::optional<CollectiveCommunication> comm;
LogMessage::Time startup_time = LogMessage::Clock::now();
Logger logger;
LoggingStreamBuffer cout_buf;
LoggingStreamBuffer cerr_buf;
LoggingStreamBuffer clog_buf;
......@@ -209,19 +211,22 @@ namespace Dune::PDELab {
// This function does the one-time setup for the sink factory, mostly
// registering default factories.
Logging::SinkFactoryRepository Logging::makeSinkFactoryRepository()
std::unique_ptr<Logging::SinkFactoryRepository> Logging::makeSinkFactoryRepository()
{
Logging::SinkFactoryRepository repo;
auto result = std::make_unique<Logging::SinkFactoryRepository>();
auto& repo = *result;
repo["file-per-rank"] = filePerRankSinkFactory;
repo["rank-0-file"] = rank0FileSinkFactory;
repo["null"] = nullSinkFactory;
return repo;
return std::move(result);
}
Logging::SinkFactoryRepository& Logging::sinkFactoryRepository()
{
static SinkFactoryRepository repository = makeSinkFactoryRepository();
return repository;
auto& holder = destructibleSingleton<SinkFactoryRepository>(makeSinkFactoryRepository);
if (not holder)
holder.create();
return holder.get();
}
Logging::SinkFactory& Logging::sinkFactory(const std::string& name)
......@@ -229,10 +234,17 @@ namespace Dune::PDELab {
return sinkFactoryRepository().at(name);
}
std::unique_ptr<Logging::State> Logging::makeState(const CollectiveCommunication* comm)
{
return std::make_unique<State>(comm);
}
Logging::State& Logging::state(const CollectiveCommunication* comm)
{
static State state(comm);
return state;
auto& holder = destructibleSingleton<State>(makeState);
if (not holder)
holder.create(comm);
return holder.get();
}
LoggerBackend& Logging::backend(std::string_view name)
......@@ -255,7 +267,12 @@ namespace Dune::PDELab {
void Logging::init(const CollectiveCommunication& comm, const ParameterTree& params)
{
// initialize singleton
using namespace std::literals;
// initialize sink factory registry singleton if necessary
sinkFactoryRepository();
// initialize state singleton
auto& s = state(&comm);
// create default sinks for stdout and stderr
......@@ -397,13 +414,28 @@ namespace Dune::PDELab {
}
}
// configure internal logger for logging system itself
{
auto level = parseLogLevel(params.get("internal.level","notice"));
auto backend = params.get("internal.backend","logging");
// create default-configured logging backend if necessary
if (backend == "logging" and s.backends.count("logging") == 0)
Logging::registerBackend("logging",s.default_backend->_default_level);
s.logger = logger(backend);
s.logger.setLevel(level);
}
if (params.get("muted",s.comm->rank() > 0))
{
mute();
if (s.comm->size() > 0)
logger().info("Muted console log sinks on MPI ranks > 0"_fmt);
s.logger.info("Muted console log sinks on MPI ranks > 0"_fmt);
}
// from here on out, it is allowed to log messages
if (params.hasKey("redirect"))
{
auto level = parseLogLevel(params["redirect"]);
......@@ -452,8 +484,36 @@ namespace Dune::PDELab {
}
}
std::time_t startup_time = std::chrono::system_clock::to_time_t(s.startup_time);
std::tm local_time;
#ifdef DUNE_HAVE_LOCALTIME_R
localtime_r(&startup_time,&local_time);
#else
std::tm* tm = std::localtime(&startup_time);
std::memcpy(&local_time,tm,sizeof(std::tm));
#endif
// We need to manually format the time, as doing so is not constexpr
auto time_string = fmt::format("{:%a %F %T %Z}",local_time);
s.logger.notice("Logging system initialized at {}"_fmt,time_string);
}
logger().notice("Logging system initialized"_fmt);
void Logging::shutdown()
{
if (isCoutRedirected())
restoreCout();
if (isCerrRedirected())
restoreCerr();
if (isClogRedirected())
restoreClog();
state().logger.notice("Shutting down logging system"_fmt);
destructibleSingleton<State>(makeState).destroy();
destructibleSingleton<SinkFactoryRepository>(makeSinkFactoryRepository).destroy();
}
bool Logging::initialized()
{
return destructibleSingleton<State>(makeState);
}
// Make not to use state() in here, this function must work before init().
......@@ -714,7 +774,7 @@ namespace Dune::PDELab {
if (not s.orig_cout_buf)
s.orig_cout_buf = std::cout.rdbuf();
std::cout.rdbuf(&s.cout_buf);
Logging::logger().notice("Redirected std::cout to backend {} with level {}, buffered: {}"_fmt,backend,level,buffered);
s.logger.info("Redirected std::cout to backend {} with level {}, buffered: {}"_fmt,backend,level,buffered);
}
void Logging::redirectCerr(std::string_view backend, LogLevel level, bool buffered)
......@@ -727,7 +787,7 @@ namespace Dune::PDELab {
if (not s.orig_cerr_buf)
s.orig_cerr_buf = std::cerr.rdbuf();
std::cerr.rdbuf(&s.cerr_buf);
Logging::logger().notice("Redirected std::cerr to backend {} with level {}, buffered: {}"_fmt,backend,level,buffered);
s.logger.info("Redirected std::cerr to backend {} with level {}, buffered: {}"_fmt,backend,level,buffered);
}
void Logging::redirectClog(std::string_view backend, LogLevel level, bool buffered)
......@@ -740,7 +800,7 @@ namespace Dune::PDELab {
if (not s.orig_clog_buf)
s.orig_clog_buf = std::clog.rdbuf();
std::clog.rdbuf(&s.clog_buf);
Logging::logger().notice("Redirected std::clog to backend {} with level {}, buffered: {}"_fmt,backend,level,buffered);
s.logger.info("Redirected std::clog to backend {} with level {}, buffered: {}"_fmt,backend,level,buffered);
}
void Logging::restoreCout()
......@@ -750,10 +810,10 @@ namespace Dune::PDELab {
{
std::cout.rdbuf(s.orig_cout_buf);
s.orig_cout_buf = nullptr;
Logging::logger().notice("Stopped redirection of std::cout"_fmt);
s.logger.notice("Stopped redirection of std::cout"_fmt);
}
else
Logging::logger().warning("Cannot stop redirection of std::cout, not redirected at the moment"_fmt);
s.logger.info("Cannot stop redirection of std::cout, not redirected at the moment"_fmt);
}
void Logging::restoreCerr()
......@@ -763,10 +823,10 @@ namespace Dune::PDELab {
{
std::cerr.rdbuf(s.orig_cerr_buf);
s.orig_cerr_buf = nullptr;
Logging::logger().notice("Stopped redirection of std::cerr"_fmt);
s.logger.info("Stopped redirection of std::cerr"_fmt);
}
else
Logging::logger().warning("Cannot stop redirection of std::cerr, not redirected at the moment"_fmt);
s.logger.warning("Cannot stop redirection of std::cerr, not redirected at the moment"_fmt);
}
void Logging::restoreClog()
......@@ -776,10 +836,10 @@ namespace Dune::PDELab {
{
std::clog.rdbuf(s.orig_clog_buf);
s.orig_clog_buf = nullptr;
Logging::logger().notice("Stopped redirection of std::clog"_fmt);
s.logger.info("Stopped redirection of std::clog"_fmt);
}
else
Logging::logger().warning("Cannot stop redirection of std::clog, not redirected at the moment"_fmt);
s.logger.warning("Cannot stop redirection of std::clog, not redirected at the moment"_fmt);
}
bool Logging::isCoutRedirected()
......
......@@ -239,9 +239,15 @@ namespace Dune::PDELab {
*
* The logging system itself supports the following configuration keys:
*
* | Key | Description |
* |-------------|----------------------------------------------------------------------------------|
* | muted | Overrides the default behavior of muting all MPI ranks with `comm.rank() > 0` |
* | Key | Description |
* |------------------|------------------------------------------------------------------------------|
* | muted | Overrides the default behavior of muting all MPI ranks with `comm.rank() > 0`|
* | internal.backend | The backend used for internal log messages of the logging system |
* | internal.level | The maximum enabled log level for internal log messages |
*
* If you do not specify configuration for the internal logging, the system defaults to a backend
* called "logger" and a maximum log level of "notice". If the backend does not exist, it will be
* created with its configuration copied from the default backend.
*
* ## Redirection of C++ Standard Streams
*
......@@ -315,7 +321,7 @@ namespace Dune::PDELab {
// Create initial sink factory repository and register default sinks
static SinkFactoryRepository makeSinkFactoryRepository();
static std::unique_ptr<SinkFactoryRepository> makeSinkFactoryRepository();
// Access the sink factory repository
static SinkFactoryRepository& sinkFactoryRepository();
......@@ -323,6 +329,9 @@ namespace Dune::PDELab {
// Get sink factory with given name
static SinkFactory& sinkFactory(const std::string& name);
// Create internal logging system state
static std::unique_ptr<State> makeState(const CollectiveCommunication* comm);
// Access the internal logging system state
static State& state(const CollectiveCommunication* = nullptr);
......@@ -357,6 +366,19 @@ namespace Dune::PDELab {
*/
static void init(const CollectiveCommunication& comm, const ParameterTree& params = {});
//! Shuts the logging system down
/**
* This function completely stops the logging system, removing all components, restoring the std streams and
* unregistering all sink factories. After calling this method, any attempt to use a still-existing logging
* component causes undefined behavior. Moreover, before calling any functions on Logging again, you must reinitialize
* the logging system by calling init(). After that call, you must obtain new logging components from the system,
* the old ones remain broken.
*/
static void shutdown();
//! Returns whether the logging system is currently initialized.
static bool initialized();
//! Registers a new SinkFactory.
/**
* Registering a new SinkFactory makes sinks of the produced type available to the ParameterTree-driven
......
......@@ -39,7 +39,8 @@ namespace Dune::PDELab {
void process(const LogMessage& msg) override
{
fmt::vprint(_stream,pattern(),arguments(msg));
PatternFormatSink::Arguments args(msg,*this);
fmt::vprint(_stream,pattern(),args);
}
private:
......
......@@ -51,7 +51,8 @@ namespace Dune::PDELab {
void process(const LogMessage& msg)
{
fmt::vprint(_file, fmt::to_string_view(pattern()), arguments(msg));
PatternFormatSink::Arguments args(msg,*this);
fmt::vprint(_file, fmt::to_string_view(pattern()), args);
}
private:
......
......@@ -99,8 +99,12 @@ namespace Dune::PDELab {
{
_local_time.emplace();
std::time_t now = std::chrono::system_clock::to_time_t(time());
#ifdef DUNE_HAVE_LOCALTIME_R
localtime_r(&now,&(*_local_time));
#else
std::tm* tm = std::localtime(&now);
std::memcpy(&(*_local_time),tm,sizeof(std::tm));
#endif
}
return *_local_time;
}
......
......@@ -199,7 +199,7 @@ namespace Dune::PDELab {
//! Returns local time of the point in time at which this message was logged.
/**
* \warning The first call to this method is rather expensive, avoid it if you don't need to
* know the absolute point im time at which log messages occured. It might be a better
* know the absolute point in time at which log messages occured. It might be a better
* alternative to record the relative time since program start instead. The return
* value is cached internally, so subsequent calls to this method on a given LogMessage
* are cheap.
......
#include "config.h"
#include <iterator>
#include <tuple>
#include <dune/pdelab/common/exceptions.hh>
#include <dune/pdelab/logging/patternformatsink.hh>
......@@ -18,24 +19,83 @@ namespace Dune::PDELab {
setPattern("{reltime:9%M:%S} {msg}");
}
// helper functions for building a fmt::format_arg_store from a tuple
template<typename T, std::size_t... i>
static auto _extract_format_args(T& args, std::index_sequence<i...>)
{
return fmt::make_format_args(std::get<i>(args)...);
}
// helper functions for building a fmt::format_arg_store from a tuple
template<typename T>
static auto extract_format_args(T& args)
{
return _extract_format_args(args,std::make_index_sequence<std::tuple_size_v<T>>{});
}
fmt::format_args PatternFormatSink::arguments(const LogMessage& msg) const
PatternFormatSink::Arguments::Arguments(const LogMessage& msg, const PatternFormatSink& sink)
{
// just package up the promised arguments. We use lazy evaluation
// for the logger name and the local time, as those are rather
// expensive.
// As fmt::format_args only stores a pointer to an array that must be held somewhere for the
// duration of related {fmt} calls, and as the format args stored in that array only hold
// references to the actual data, we must store both the objects returned by the accessors of
// the log message etc. and a fmt::format_arg_store for the array of format arguments.
// Extract and store data items in a tuple within an internal buffer.
// We use lazy evaluation for the logger name and the local time, as those are rather expensive.
// IMPORTANT: Update itemIndex() when making changes to this list!
return fmt::make_format_args(
using Data = std::tuple<
std::string_view,
std::string_view,
std::string_view,
LogMessage::Duration,
decltype(SinkMessageItems::relativeDays(msg)),
decltype(SinkMessageItems::localTime(msg)),
decltype(SinkMessageItems::backend(msg,sink.widestLogger())),
std::string_view
>;
// Make sure our data actually fits into the buffer
static_assert(
sizeof(Data) <= ArgumentDataBufferSize,
"Pattern format data does not fit into buffer"
);
auto data = new(_data_buffer) Data(
msg.payload(),
Dune::PDELab::name(msg.level()),
paddedName(msg.level()),
msg.relativeTime(),
SinkMessageItems::relativeDays(msg),
SinkMessageItems::localTime(msg),
SinkMessageItems::backend(msg,widestLogger()),
name()
SinkMessageItems::backend(msg,sink.widestLogger()),
sink.name()
);
// If Data is not trivially destructible, we have to arrange for its destructor to be called
// in our destructor
if (not std::is_trivially_destructible_v<Data>)
{
_cleanup = [data]()
{
data->~Data();
};
}
// Make sure the format_arg_store actually fits into its bufffer
static_assert(
sizeof(decltype(extract_format_args(*data))) <= ArgumentArgsBufferSize,
"Pattern format_arg_store does not fit into buffer"
);
// fmt::format_arg_store is always trivially destructible
auto args = new(_args_buffer) auto(extract_format_args(*data));
// store type-erased data
_args = *args;
}
std::size_t PatternFormatSink::itemIndex(std::string_view item)
......@@ -163,10 +223,10 @@ namespace Dune::PDELab {
}
void PatternFormatSink::setParameters(PatternFormatSink& sink, const ParameterTree& params)
void PatternFormatSink::setPatternFormatParameters(const ParameterTree& params)
{
if (params.hasKey("pattern"))
sink.setPattern(params["pattern"]);
setPattern(params["pattern"]);
}
......
......@@ -2,6 +2,7 @@
#define DUNE_PDELAB_LOGGING_PATTERNFORMATSINK_HH
#include <cstdio>
#include <functional>
#include <string_view>
#include <dune/common/parametertree.hh>
......@@ -55,14 +56,62 @@ namespace Dune::PDELab {
* You can set the pattern via the ParameterTree key "pattern".
*
* As a programmer, you use this class by inheriting from it. In your `process()` implementation,
* you call pattern() and arguments() and pass those to a version of `fmt::vformat()` or
* `fmt::vprint()`.
* create a named instance of `Arguments` and pass it to a version of `fmt::vformat()` or
* `fmt::vprint()`, together with the pattern obtained by calling `pattern()`.
*/
class PatternFormatSink
: public Sink
{
public:
protected:
static constexpr std::size_t ArgumentDataBufferSize = 200;
static constexpr std::size_t ArgumentArgsBufferSize = 200;
//! Stores the required arguments for the pattern.
/**
* This class provides opaque storage for the format arguments required by
* the current pattern. An object of this type should be constructed in
* derived classes before formatting the pattern. This type implicitly casts
* to `fmt::format_args`, which can be used passed to the {fmt} formatting
* functions.
*
* \note You **must** create a named object of this type; trying to feed a
* temporary object to {}fmt} will cause a compiler error.
*/
class Arguments
{
fmt::format_args _args;
std::function<void()> _cleanup;
char* _data_buffer[ArgumentDataBufferSize];
char* _args_buffer[ArgumentArgsBufferSize];
public:
//! Create argument store for the given LogMessage and PatternFormatSink.
Arguments(const LogMessage&, const PatternFormatSink&);
//! Arguments cannot be copied or moved.
Arguments(const Arguments&) = delete;
//! Arguments cannot be copied or moved.
Arguments& operator=(const Arguments&) = delete;
//! Free any resources allocated by Arguments.
~Arguments()
{
if (_cleanup)
_cleanup();
}
//! Named variables of type Arguments cast implicitly into `fmt::format_args`.
operator fmt::format_args&() &
{
return _args;
}
};
//! Constructs a PatternFormatSink with the default pattern "{reltime:9%M:%S} {msg}".
PatternFormatSink(
......@@ -72,7 +121,9 @@ namespace Dune::PDELab {
);
//! Constructs a {fmt} argument list from the LogMessage that can be used to format the stored pattern.
fmt::format_args arguments(const LogMessage& msg) const;
Arguments arguments(const LogMessage& msg) const;
public:
//! Returns the {fmt} format pattern for formatting the log messages for this sink.
/**
......@@ -109,8 +160,8 @@ namespace Dune::PDELab {
//! Returns the index of a named log message item.
static std::size_t itemIndex(std::string_view item);
//! Parses the ParameterTree for applicable parameters and applies then to the given ParameterSink.
static void setParameters(PatternFormatSink& sink, const ParameterTree& params);
//! Parses the ParameterTree for applicable parameters and applies then to this sink.
void setPatternFormatParameters(const ParameterTree& params);
private:
......