Skip to content

Commit

Permalink
Revisit log_map and experimental user_bench utils
Browse files Browse the repository at this point in the history 
Replaces `log_map` (which was an `std::unordered_map`) with `std::tuple`
to have less runtime overhead and allow for arbitrary types to be logged.

Changes to `user_bench` utilities:
  - Logging through `log_map` is no longer supported.
  - Replace `log_user_config` by `log_once` function to log messages
    only on master node.
  - Print delta time since previous event.
  - Ensure thread safety for all functions.
  • Loading branch information
@psalz
psalz committed Feb 9, 2022
1 parent 3c4fc11 commit fd3ddd4
Show file tree
Hide file tree
Showing 4 changed files with 84 additions and 55 deletions.
47 changes: 32 additions & 15 deletions include/log.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@
#include <string>
#include <string_view>
#include <unordered_map>
#include <utility>
#include <variant>

// TODO: Make this configurable through CMake?
Expand All @@ -26,13 +27,22 @@
namespace celerity {
namespace detail {

using log_map = std::unordered_map<std::string, std::variant<std::string_view, size_t>>;
using log_level = spdlog::level::level_enum;

template <typename... Es>
struct log_map {
const std::tuple<Es...>& entries;
log_map(const std::tuple<Es...>& entries) : entries(entries) {}
};

struct log_context {
std::string value;
log_context() = default;
explicit log_context(const log_map& values) { value = fmt::format("[{}] ", values); }
template <typename... Es>
explicit log_context(const std::tuple<Es...>& entries) {
static_assert(sizeof...(Es) % 2 == 0, "log_context requires key/value pairs");
value = fmt::format("[{}] ", log_map{entries});
}
};

inline const std::string null_log_ctx;
Expand All @@ -46,28 +56,35 @@ namespace detail {
#define CELERITY_DETAIL_LOG_SET_SCOPED_CTX(ctx) \
log_ctx_setter _set_log_ctx_##__COUNTER__ { ctx }

template <typename A, typename B, typename... Rest, size_t... Is, typename Callback>
constexpr void tuple_for_each_pair_impl(const std::tuple<A, B, Rest...>& tuple, Callback&& cb, std::index_sequence<Is...>) {
cb(std::get<0>(tuple), std::get<1>(tuple));
if constexpr(sizeof...(Rest) > 0) {
tuple_for_each_pair_impl(std::tuple{std::get<2 + Is>(tuple)...}, std::forward<Callback>(cb), std::make_index_sequence<sizeof...(Rest)>{});
}
}

template <typename... Es, typename Callback>
constexpr void tuple_for_each_pair(const std::tuple<Es...>& tuple, Callback&& cb) {
static_assert(sizeof...(Es) % 2 == 0, "an even number of entries is required");
tuple_for_each_pair_impl(tuple, std::forward<Callback>(cb), std::make_index_sequence<sizeof...(Es) - 2>{});
}

} // namespace detail
} // namespace celerity

template <>
struct fmt::formatter<celerity::detail::log_map> {
template <typename... Es>
struct fmt::formatter<celerity::detail::log_map<Es...>> {
constexpr auto parse(format_parse_context& ctx) { return ctx.begin(); }

template <typename FormatContext>
auto format(const celerity::detail::log_map& map, FormatContext& ctx) {
auto format(const celerity::detail::log_map<Es...>& map, FormatContext& ctx) {
auto&& out = ctx.out();
int i = 0;
for(const auto& [k, v] : map) {
tuple_for_each_pair(map.entries, [&i, &out](auto& a, auto& b) {
if(i++ > 0) { fmt::format_to(out, ", "); }
fmt::format_to(out, "{}=", k);
if(std::holds_alternative<std::string_view>(v)) {
fmt::format_to(out, "{}", std::get<std::string_view>(v));
} else if(std::holds_alternative<size_t>(v)) {
fmt::format_to(out, "{}", std::get<size_t>(v));
} else {
assert(false);
}
}
fmt::format_to(out, "{}={}", a, b);
});
return out;
}
};
61 changes: 38 additions & 23 deletions include/user_bench.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,10 @@

#include <chrono>
#include <memory>
#include <mutex>
#include <stack>
#include <string>
#include <string_view>

#include "log.h"
#include "types.h"
Expand All @@ -16,7 +19,6 @@ namespace experimental {
namespace bench {
namespace detail {
using node_id = celerity::detail::node_id;
using log_map = celerity::detail::log_map;
using config = celerity::detail::config;

class user_benchmarker {
Expand All @@ -26,24 +28,30 @@ namespace experimental {
user_benchmarker(user_benchmarker&&) = delete;
~user_benchmarker();

void log_user_config(log_map lm) const;

template <typename... Args>
void begin(const char* fmt, Args... args) {
begin_section(fmt::format(fmt, std::forward<Args>(args)...));
void log_once(const std::string& format_string, Args&&... args) const {
if(this_nid == 0) { log(format_string, std::forward<Args>(args)...); }
}

template <typename... Args>
void end(const char* fmt, Args... args) {
end_section(fmt::format(fmt, std::forward<Args>(args)...));
void begin(std::string_view format_string, Args&&... args) {
begin_section(fmt::format(format_string, std::forward<Args>(args)...));
}

template <typename... Args>
void event(const char* fmt, Args... args) {
log_event(fmt::format(fmt, std::forward<Args>(args)...));
void end(std::string_view format_string, Args&&... args) {
end_section(fmt::format(format_string, std::forward<Args>(args)...));
}

void event(const log_map& lm) const { log_event(lm); }
template <typename... Args>
void event(const std::string& format_string, Args&&... args) {
std::lock_guard lk{mutex};
const auto now = bench_clock::now();
const auto dt =
(last_event_tp != bench_clock::time_point{}) ? std::chrono::duration_cast<std::chrono::microseconds>(now - last_event_tp).count() : 0;
log(format_string + " (+{}us)", std::forward<Args>(args)..., dt);
last_event_tp = now;
}

private:
using bench_clock = std::chrono::steady_clock;
Expand All @@ -54,52 +62,59 @@ namespace experimental {
bench_clock::time_point start;
};

mutable std::mutex mutex;

node_id this_nid;
section_id next_section_id = 0;
std::stack<section> sections;
bench_clock::time_point last_event_tp = {};

void begin_section(std::string name);
void end_section(std::string name);
void log_event(const std::string& message) const;
void log_event(log_map lm) const;
void end_section(const std::string& name);

template <typename... Args>
void log(const std::string& format_string, Args&&... args) const {
spdlog::default_logger_raw()->log(spdlog::level::info, "[user] " + format_string, std::forward<Args>(args)...);
}
};

user_benchmarker& get_user_benchmarker();
} // namespace detail

/**
* @brief Logs structured user configuration data. Only logged once (on the master node).
* @brief Logs a message only once (on the master node).
*/
inline void log_user_config(const detail::log_map& lm) { detail::get_user_benchmarker().log_user_config(lm); }
template <typename... Args>
void log_once(const std::string& format_string, Args&&... args) {
detail::get_user_benchmarker().log_once(format_string, std::forward<Args>(args)...);
}

/**
* @brief Begins a new benchmarking section.
*
* Sections can be nested to any depth.
*/
template <typename... Args>
void begin(const char* bench_section_fmt, Args... args) {
detail::get_user_benchmarker().begin(bench_section_fmt, std::forward<Args>(args)...);
void begin(std::string_view format_string, Args&&... args) {
detail::get_user_benchmarker().begin(format_string, std::forward<Args>(args)...);
}

/**
* @brief Ends an existing benchmarking section.
*/
template <typename... Args>
void end(const char* bench_section_fmt, Args... args) {
detail::get_user_benchmarker().end(bench_section_fmt, std::forward<Args>(args)...);
void end(std::string_view format_string, Args&&... args) {
detail::get_user_benchmarker().end(format_string, std::forward<Args>(args)...);
}

/**
* @brief Logs a benchmarking event.
*/
template <typename... Args>
void event(const char* event_fmt, Args... args) {
detail::get_user_benchmarker().event(event_fmt, std::forward<Args>(args)...);
void event(const std::string& format_string, Args&&... args) {
detail::get_user_benchmarker().event(format_string, std::forward<Args>(args)...);
}

inline void event(const detail::log_map& lm) { detail::get_user_benchmarker().event(lm); }

} // namespace bench
} // namespace experimental
} // namespace celerity
9 changes: 5 additions & 4 deletions include/worker_job.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -36,7 +36,8 @@ namespace detail {
bool is_done() const { return done; }

protected:
worker_job(command_pkg pkg, log_map ctx = {}) : pkg(pkg), lctx((ctx.insert({"job", pkg.cid}), ctx)) {}
template <typename... Es>
worker_job(command_pkg pkg, std::tuple<Es...> ctx = {}) : pkg(pkg), lctx(std::tuple_cat(std::make_tuple("job", pkg.cid), ctx)) {}

private:
command_pkg pkg;
Expand Down Expand Up @@ -102,7 +103,7 @@ namespace detail {

class reduction_job : public worker_job {
public:
reduction_job(command_pkg pkg, reduction_manager& rm) : worker_job(pkg, {{"rid", std::get<reduction_data>(pkg.data).rid}}), rm(rm) {
reduction_job(command_pkg pkg, reduction_manager& rm) : worker_job(pkg, std::make_tuple("rid", std::get<reduction_data>(pkg.data).rid)), rm(rm) {
assert(pkg.cmd == command_type::REDUCTION);
}

Expand All @@ -117,7 +118,7 @@ namespace detail {
class host_execute_job : public worker_job {
public:
host_execute_job(command_pkg pkg, detail::host_queue& queue, detail::task_manager& tm, buffer_manager& bm)
: worker_job(pkg, {{"tid", std::get<task_data>(pkg.data).tid}}), queue(queue), task_mngr(tm), buffer_mngr(bm) {
: worker_job(pkg, std::make_tuple("tid", std::get<task_data>(pkg.data).tid)), queue(queue), task_mngr(tm), buffer_mngr(bm) {
assert(pkg.cmd == command_type::TASK);
}

Expand All @@ -139,7 +140,7 @@ namespace detail {
class device_execute_job : public worker_job {
public:
device_execute_job(command_pkg pkg, detail::device_queue& queue, detail::task_manager& tm, buffer_manager& bm, reduction_manager& rm, node_id local_nid)
: worker_job(pkg, {{"tid", std::get<task_data>(pkg.data).tid}}), queue(queue), task_mngr(tm), buffer_mngr(bm), reduction_mngr(rm),
: worker_job(pkg, std::make_tuple("tid", std::get<task_data>(pkg.data).tid)), queue(queue), task_mngr(tm), buffer_mngr(bm), reduction_mngr(rm),
local_nid(local_nid) {
assert(pkg.cmd == command_type::TASK);
}
Expand Down
22 changes: 9 additions & 13 deletions src/user_bench.cc
View file
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
#include "user_bench.h"

#include <ratio>
#include <stdexcept>

#include "config.h"
#include "runtime.h"
Expand All @@ -16,10 +17,6 @@ namespace experimental {
}
}

void user_benchmarker::log_user_config(log_map lm) const {
if(this_nid == 0) { CELERITY_INFO("User config: {}", lm); }
}

user_benchmarker::user_benchmarker(config& cfg, node_id this_nid) : this_nid(this_nid) {
if(static_cast<double>(bench_clock::period::num) / bench_clock::period::den > static_cast<double>(std::micro::num) / std::micro::den) {
CELERITY_WARN("Available clock does not have sufficient precision");
Expand All @@ -29,22 +26,21 @@ namespace experimental {
user_benchmarker& get_user_benchmarker() { return celerity::detail::runtime::get_instance().get_user_benchmarker(); }

void user_benchmarker::begin_section(std::string name) {
const section sec = {next_section_id++, name, bench_clock::now()};
sections.push(sec);
CELERITY_INFO("Begin section {}: \"{}\"", sec.id, name);
std::lock_guard lk{mutex};
section sec = {next_section_id++, std::move(name), bench_clock::now()};
log("Begin section {} \"{}\"", sec.id, sec.name);
sections.push(std::move(sec));
}

void user_benchmarker::end_section(std::string name) {
void user_benchmarker::end_section(const std::string& name) {
std::lock_guard lk{mutex};
const auto sec = sections.top();
sections.pop();
assert(sec.name == name && "Section name does not equal last section");
if(sec.name != name) { throw std::runtime_error(fmt::format("Section name '{}' does not match last section '{}'", name, sec.name)); }
const auto duration = std::chrono::duration_cast<std::chrono::microseconds>(bench_clock::now() - sec.start);
CELERITY_INFO("End section {}: \"{}\". Duration {}us", sec.id, name, duration.count());
log("End section {} \"{}\" after {}us", sec.id, name, duration.count());
}

void user_benchmarker::log_event(const std::string& message) const { CELERITY_INFO("User event: \"{}\"", message); }

void user_benchmarker::log_event(log_map lm) const { CELERITY_INFO("User event: {}", lm); }
} // namespace detail
} // namespace bench
} // namespace experimental
Expand Down

0 comments on commit fd3ddd4

Please sign in to comment.