23 #include <rapidjson/document.h> 24 #include <rapidjson/stringbuffer.h> 25 #include <rapidjson/writer.h> 27 #include <boost/algorithm/string.hpp> 28 #include <boost/log/expressions.hpp> 29 #include <boost/log/sinks.hpp> 30 #include <boost/log/sources/global_logger_storage.hpp> 31 #include <boost/log/sources/logger.hpp> 32 #include <boost/log/sources/severity_feature.hpp> 33 #include <boost/log/support/date_time.hpp> 34 #include <boost/log/utility/setup.hpp> 35 #include <boost/phoenix.hpp> 36 #include <boost/smart_ptr/weak_ptr.hpp> 37 #include <boost/variant.hpp> 47 namespace attr = boost::log::attributes;
48 namespace expr = boost::log::expressions;
49 namespace keywords = boost::log::keywords;
50 namespace sinks = boost::log::sinks;
51 namespace sources = boost::log::sources;
52 namespace po = boost::program_options;
54 BOOST_LOG_ATTRIBUTE_KEYWORD(process_id,
"ProcessID", attr::current_process_id::value_type)
55 BOOST_LOG_ATTRIBUTE_KEYWORD(channel,
"Channel",
Channel)
56 BOOST_LOG_ATTRIBUTE_KEYWORD(severity,
"Severity",
Severity)
58 BOOST_LOG_GLOBAL_LOGGER_DEFAULT(gChannelLogger,
ChannelLogger)
63 return boost::filesystem::path(path).filename().string();
68 std::string
const base_name =
69 argv0 ==
nullptr ? std::string(
"omnisci_server") :
filename(argv0);
87 po::command_line_parser(argc, argv).options(*options_).allow_unregistered().run(),
99 options_ = std::make_unique<boost::program_options::options_description>(
"Logging");
100 std::string
const channels =
104 [](
auto a,
auto channel) {
return a +
' ' + channel; });
106 std::string severities;
108 if (!boost::algorithm::starts_with(
name,
"DEBUG")) {
109 (severities += (severities.empty() ?
"" :
" ")) +=
name;
115 "Logging directory. May be relative to data directory, or absolute.");
119 "Log file name relative to log-directory.");
120 options_->add_options()(
"log-symlink",
122 "Symlink to active log.");
123 options_->add_options()(
"log-severity",
125 (
"Log to file severity level: " + severities).c_str());
129 (
"Log to console severity level: " + severities).c_str());
130 options_->add_options()(
"log-channels",
132 (
"Log channel debug info: " + channels).c_str());
133 options_->add_options()(
"log-auto-flush",
135 "Flush logging buffer to file after each message.");
136 options_->add_options()(
"log-max-files",
138 "Maximum number of log files to keep.");
140 "log-min-free-space",
142 "Minimum number of bytes left on device before oldest log files are deleted.");
143 options_->add_options()(
"log-rotate-daily",
145 "Start new log files at midnight.");
149 "Maximum file size in bytes before new log files are started.");
152 template <
typename TAG>
154 constexpr std::regex::flag_type flags = std::regex::ECMAScript | std::regex::optimize;
155 static std::regex
const regex(R
"(\{SEVERITY\})", flags); 156 if (std::is_same<TAG, Channel>::value) {
157 return std::regex_replace(str, regex,
ChannelNames[tag]);
165 boost::log::value_ref<boost::log::attributes::current_process_id::value_type,
166 tag::process_id>
const& pid) {
167 return pid ? pid->native_id() : 0;
170 template <
typename SINK>
172 boost::weak_ptr<SINK> weak_ptr,
173 std::string&& symlink) {
174 namespace fs = boost::filesystem;
176 symlink = std::move(symlink)](sinks::text_file_backend::stream_type& stream) {
177 if (boost::shared_ptr<SINK> sink = weak_ptr.lock()) {
178 boost::system::error_code ec;
179 fs::path
const& file_name = sink->locked_backend()->get_current_file_name();
180 fs::path
const symlink_path = file_name.parent_path() / symlink;
181 fs::remove(symlink_path, ec);
183 stream <<
filename(__FILE__) <<
':' << __LINE__ <<
' ' << ec.message() <<
'\n';
185 fs::create_symlink(file_name.filename(), symlink_path, ec);
187 stream <<
filename(__FILE__) <<
':' << __LINE__ <<
' ' << ec.message() <<
'\n';
194 boost::log::formatting_ostream& strm,
195 boost::log::to_log_manip<Channel, tag::channel>
const& manip) {
200 boost::log::formatting_ostream& strm,
201 boost::log::to_log_manip<Severity, tag::severity>
const& manip) {
205 template <
typename TAG,
typename SINK>
207 if (std::is_same<TAG, Channel>::value) {
209 expr::stream << expr::format_date_time<boost::posix_time::ptime>(
210 "TimeStamp",
"%Y-%m-%dT%H:%M:%S.%f")
211 <<
' ' << channel <<
' ' 213 <<
' ' << expr::smessage);
216 expr::stream << expr::format_date_time<boost::posix_time::ptime>(
217 "TimeStamp",
"%Y-%m-%dT%H:%M:%S.%f")
218 <<
' ' << severity <<
' ' 220 <<
' ' << expr::smessage);
224 template <
typename FILE_SINK,
typename TAG>
228 auto sink = boost::make_shared<FILE_SINK>(
229 keywords::file_name =
233 if (std::is_same<TAG, Channel>::value) {
234 sink->set_filter(channel == static_cast<Channel>(tag));
235 set_formatter<Channel>(sink);
240 : static_cast<Severity>(tag);
241 sink->set_filter(min_filter_level <= severity);
242 set_formatter<Severity>(sink);
244 typename FILE_SINK::locked_backend_ptr backend = sink->locked_backend();
246 backend->set_time_based_rotation(sinks::file::rotation_at_time_point(0, 0, 0));
248 backend->set_file_collector(
249 sinks::file::make_collector(keywords::target = full_log_dir,
254 backend->scan_for_files();
262 using ClogSync = sinks::synchronous_sink<sinks::text_ostream_backend>;
263 using FileSync = sinks::synchronous_sink<sinks::text_file_backend>;
265 template <
typename CONSOLE_SINK>
267 auto sink = boost::make_shared<CONSOLE_SINK>();
268 boost::shared_ptr<std::ostream> clog(&std::clog, boost::null_deleter());
269 sink->locked_backend()->add_stream(clog);
271 set_formatter<Severity>(sink);
281 boost::shared_ptr<boost::log::core> core = boost::log::core::get();
283 core->add_global_attribute(
"TimeStamp", attr::local_clock());
284 core->add_global_attribute(
"ProcessID", attr::current_process_id());
287 bool const log_dir_was_created = boost::filesystem::create_directory(full_log_dir);
292 core->add_sink(make_sink<FileSync>(log_opts, full_log_dir, level));
295 if (log_dir_was_created) {
296 LOG(
INFO) <<
"Log directory(" << full_log_dir.native() <<
") created.";
298 for (
auto const channel : log_opts.
channels_) {
299 core->add_sink(make_sink<FileSync>(log_opts, full_log_dir, channel));
303 core->add_sink(make_sink<ClogSync>(log_opts));
309 throw std::runtime_error(
310 "logger::set_once_fatal_func() should not be called more than once.");
315 static std::once_flag logger_flag;
316 std::call_once(logger_flag, []() { boost::log::core::get()->remove_all_sinks(); });
324 if (1 < str.size() && (str.front() ==
'\'' || str.front() ==
'"') &&
325 str.front() == str.back()) {
326 str.erase(str.size() - 1, 1);
336 std::getline(in, line);
338 std::regex
const rex(R
"(\w+)"); 339 using TokenItr = std::regex_token_iterator<std::string::iterator>;
341 for (TokenItr tok(line.begin(), line.end(), rex); tok !=
end; ++tok) {
344 in.setstate(std::ios_base::failbit);
347 channels.emplace(static_cast<Channel>(itr -
ChannelNames.cbegin()));
356 for (
auto const channel : channels) {
369 in.setstate(std::ios_base::failbit);
383 , enum_value_(channel)
384 , record_(
std::make_unique<
boost::log::record>(
385 gChannelLogger::get().open_record(
boost::log::keywords::channel = channel))) {
387 stream_ = std::make_unique<boost::log::record_ostream>(*record_);
394 ,
record_(
std::make_unique<
boost::log::record>(gSeverityLogger::get().open_record(
395 boost::log::keywords::severity = severity))) {
397 stream_ = std::make_unique<boost::log::record_ostream>(*record_);
404 gChannelLogger::get().push_record(boost::move(
stream_->get_record()));
406 gSeverityLogger::get().push_record(boost::move(
stream_->get_record()));
419 Logger::operator bool()
const {
420 return static_cast<bool>(
stream_);
428 using Clock = std::chrono::steady_clock;
450 : duration_tree_(duration_tree)
451 , start_(
Clock::now())
453 , severity_(severity)
459 template <
typename Units = std::chrono::milliseconds>
460 typename Units::rep relative_start_time()
const;
462 template <
typename Units = std::chrono::milliseconds>
463 typename Units::rep value()
const;
479 : current_depth_(start_depth + bool(start_depth))
480 , depth_(start_depth)
481 , start_(
Clock::now())
482 , thread_id_(thread_id) {}
484 durations_.emplace_back(duration_tree);
487 CHECK(!durations_.empty());
488 return boost::get<Duration>(durations_.front());
493 template <
typename... Ts>
495 durations_.emplace_back(
Duration(
this, current_depth_++, std::forward<Ts>(
args)...));
496 return boost::get<Duration>(&durations_.back());
503 stop_ = Clock::now();
504 duration_tree_->decrementDepth();
508 template <
typename Units>
510 return std::chrono::duration_cast<Units>(start_ - duration_tree_->start_).count();
513 template <
typename Units>
515 return std::chrono::duration_cast<Units>(stop_ - start_).count();
530 template <
typename... Ts>
535 if (!duration_tree_ptr) {
536 duration_tree_ptr = std::make_unique<DurationTree>(
g_thread_id, 0);
538 return duration_tree_ptr->newDuration(severity, std::forward<Ts>(
args)...);
544 return os << std::setw(2 * duration.
depth_) <<
' ' << duration.
value() <<
"ms start(" 550 os << std::setw(2 * duration_tree.
depth_) <<
' ' <<
"New thread(" 552 for (
auto const& duration_tree_node : duration_tree.
durations()) {
553 os <<
'\n' << duration_tree_node;
556 << std::setw(2 * duration_tree.
depth_) <<
' ' <<
"End thread(" 561 boost::log::record_ostream&
operator<<(boost::log::record_ostream& os,
562 DurationTreeMap::const_reference kv_pair) {
563 auto itr = kv_pair.second->durations().cbegin();
564 auto const end = kv_pair.second->durations().cend();
565 auto const& root_duration = boost::get<Duration>(*itr);
566 os <<
"DEBUG_TIMER thread_id(" << kv_pair.first <<
")\n" 567 << root_duration.value() <<
"ms total duration for " << root_duration.name_;
568 for (++itr; itr !=
end; ++itr) {
581 std::shared_ptr<rapidjson::Document>
doc_;
582 rapidjson::Document::AllocatorType&
alloc_;
584 DurationTreeNodes::const_iterator
begin_;
585 DurationTreeNodes::const_iterator
end_;
588 DurationTreeNodes::const_iterator begin,
589 DurationTreeNodes::const_iterator
end)
590 : doc_(json_encoder.doc_), alloc_(doc_->GetAllocator()), begin_(begin), end_(end) {}
595 , alloc_(doc_->GetAllocator()) {}
597 rapidjson::Value retval(rapidjson::kObjectType);
598 retval.AddMember(
"type",
"duration", alloc_);
599 retval.AddMember(
"duration_ms", rapidjson::Value(duration.
value()), alloc_);
602 retval.AddMember(
"name", rapidjson::StringRef(duration.
name_), alloc_);
604 retval.AddMember(
"line", rapidjson::Value(duration.
line_), alloc_);
605 retval.AddMember(
"children", childNodes(duration.
depth_), alloc_);
609 begin_ = duration_tree.
durations().cbegin();
611 rapidjson::Value retval(rapidjson::kObjectType);
612 retval.AddMember(
"type",
"duration_tree", alloc_);
614 retval.AddMember(
"children", childNodes(duration_tree.
depth_), alloc_);
619 rapidjson::Value children(rapidjson::kArrayType);
620 for (
auto itr = begin_; itr != end_; ++itr) {
621 int const depth = apply_visitor(get_depth, *itr);
622 if (depth <= parent_depth) {
625 if (depth == parent_depth + 1) {
626 JsonEncoder json_encoder(*
this, std::next(itr), end_);
627 children.PushBack(apply_visitor(json_encoder, *itr), alloc_);
634 rapidjson::Value
timer(DurationTreeMap::const_reference kv_pair) {
635 begin_ = kv_pair.second->durations().cbegin();
636 end_ = kv_pair.second->durations().cend();
637 rapidjson::Value retval(rapidjson::kObjectType);
638 if (begin_ != end_) {
639 auto const& root_duration = boost::get<Duration>(*(begin_++));
640 retval.AddMember(
"type",
"root", alloc_);
641 retval.AddMember(
"thread_id",
std::to_string(kv_pair.first), alloc_);
643 "total_duration_ms", rapidjson::Value(root_duration.value()), alloc_);
644 retval.AddMember(
"name", rapidjson::StringRef(root_duration.name_), alloc_);
645 retval.AddMember(
"children", childNodes(0), alloc_);
650 std::string
str(DurationTreeMap::const_reference kv_pair) {
651 doc_->AddMember(
"timer", timer(kv_pair), alloc_);
652 rapidjson::StringBuffer buffer;
653 rapidjson::Writer<rapidjson::StringBuffer> writer(buffer);
654 doc_->Accept(writer);
655 return {buffer.GetString(), buffer.GetSize()};
661 void operator()(DurationTreeMap::const_iterator
const& itr)
const {
662 for (
auto const& duration_tree_node : itr->second->durations()) {
663 apply_visitor(*
this, duration_tree_node);
669 for (
auto const& duration_tree_node : duration_tree.
durations()) {
670 apply_visitor(*
this, duration_tree_node);
680 auto const& root_duration = itr->second->rootDuration();
681 if (
auto log =
Logger(root_duration.severity_)) {
682 log.stream(root_duration.file_, root_duration.line_) << *itr;
686 *json_str = json_encoder.
str(*itr);
689 erase_duration_trees(itr);
693 : duration_(
newDuration(severity, file, line, name)) {}
725 auto const current_depth = parent_itr->second->currentDepth();
727 CHECK(!duration_tree_ptr) << __func__ <<
" called twice on same thread.";
728 duration_tree_ptr = std::make_unique<DurationTree>(
g_thread_id, current_depth + 1);
729 parent_itr->second->pushDurationTree(*duration_tree_ptr);
738 #endif // #ifndef __CUDACC__ std::istream & operator>>(std::istream &in, Channels &channels)
DurationTreeNodes::const_iterator end_
void pushDurationTree(DurationTree &duration_tree)
const Duration & rootDuration() const
void debug_timer_new_thread(ThreadId parent_thread_id)
std::unique_ptr< boost::program_options::options_description > options_
constexpr std::array< char const *, 3 > ChannelNames
std::string filename(char const *path)
void operator()(Duration const &) const
std::string replace_braces(std::string const &str, TAG const tag)
std::set< Channel > Channels
std::string stopAndGetJson()
Units::rep relative_start_time() const
std::mutex g_duration_tree_map_mutex
boost::log::sources::channel_logger_mt< Channel > ChannelLogger
void set_formatter(SINK &sink)
std::unique_ptr< boost::log::record > record_
LogOptions(char const *argv0)
JsonEncoder(JsonEncoder &json_encoder, DurationTreeNodes::const_iterator begin, DurationTreeNodes::const_iterator end)
sinks::text_file_backend::open_handler_type create_or_replace_symlink(boost::weak_ptr< SINK > weak_ptr, std::string &&symlink)
std::once_flag g_fatal_func_flag
void operator()(DurationTree const &duration_tree) const
Duration * newDuration(Severity severity, Ts &&... args)
Clock::time_point const start_
Duration(DurationTree *duration_tree, int depth, Severity severity, char const *file, int line, char const *name)
bool g_enable_debug_timer
const std::string json_str(const rapidjson::Value &obj) noexcept
DurationTreeNodes durations_
Duration * newDuration(Ts &&... args)
Clock::time_point const start_
boost::program_options::options_description const & get_options() const
rapidjson::Value operator()(Duration const &duration)
Depth-first search and erase all DurationTrees. Not thread-safe.
int operator()(Duration const &duration) const
rapidjson::Value childNodes(int const parent_depth)
std::unordered_map< ThreadId, std::unique_ptr< DurationTree > > DurationTreeMap
void set_once_fatal_func(FatalFunc fatal_func)
constexpr std::array< char, 3 > ChannelSymbols
sinks::synchronous_sink< sinks::text_ostream_backend > ClogSync
void(*)() noexcept FatalFunc
constexpr std::array< char, 8 > SeveritySymbols
DurationTreeNodes::const_iterator begin_
void logAndEraseDurationTree(std::string *json_str)
sinks::synchronous_sink< sinks::text_file_backend > FileSync
rapidjson::Value operator()(DurationTree const &duration_tree)
void init(LogOptions const &log_opts)
std::deque< DurationTreeNode > DurationTreeNodes
Severity g_min_active_severity
std::atomic< FatalFunc > g_fatal_func
DebugTimer(Severity, char const *file, int line, char const *name)
ThreadId thread_local const g_thread_id
void operator()(DurationTreeMap::const_iterator const &itr) const
boost::shared_ptr< FILE_SINK > make_sink(LogOptions const &log_opts, boost::filesystem::path const &full_log_dir, TAG const tag)
std::atomic< ThreadId > g_next_thread_id
DurationTree(ThreadId thread_id, int start_depth)
DurationTree *const duration_tree_
ThreadId const thread_id_
std::unique_ptr< boost::log::record_ostream > stream_
int operator()(DurationTree const &duration_tree) const
boost::log::formatting_ostream & operator<<(boost::log::formatting_ostream &strm, boost::log::to_log_manip< Channel, tag::channel > const &manip)
constexpr std::array< char const *, 8 > SeverityNames
boost::filesystem::path full_log_dir() const
rapidjson::Value timer(DurationTreeMap::const_reference kv_pair)
std::string str(DurationTreeMap::const_reference kv_pair)
bool g_any_active_channels
boost::log::sources::severity_logger_mt< Severity > SeverityLogger
std::string file_name_pattern_
void set_base_path(std::string const &base_path)
DurationTreeMap g_duration_tree_map
std::chrono::steady_clock Clock
boost::log::attributes::current_process_id::value_type::native_type get_native_process_id(boost::log::value_ref< boost::log::attributes::current_process_id::value_type, tag::process_id > const &pid)
void unquote(std::string &str)
std::shared_ptr< rapidjson::Document > doc_
DEVICE auto accumulate(ARGS &&... args)
boost::variant< Duration, DurationTree & > DurationTreeNode
boost::filesystem::path log_dir_
DurationTreeNodes const & durations() const
rapidjson::Document::AllocatorType & alloc_
boost::log::record_ostream & stream(char const *file, int line)
void parse_command_line(int, char const *const *)