OmniSciDB  06b3bd477c
 All Classes Namespaces Files Functions Variables Typedefs Enumerations Enumerator Friends Macros Pages
Logger.cpp
Go to the documentation of this file.
1 /*
2  * Copyright 2019 OmniSci, Inc.
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  * http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15  */
16 
18 
19 #ifndef __CUDACC__
20 
21 #include "Logger.h"
22 #include "StringTransform.h"
23 
24 #include <rapidjson/document.h>
25 #include <rapidjson/stringbuffer.h>
26 #include <rapidjson/writer.h>
27 
28 #include <boost/algorithm/string.hpp>
29 #include <boost/log/expressions.hpp>
30 #include <boost/log/sinks.hpp>
31 #include <boost/log/sources/global_logger_storage.hpp>
32 #include <boost/log/sources/logger.hpp>
33 #include <boost/log/sources/severity_feature.hpp>
34 #include <boost/log/support/date_time.hpp>
35 #include <boost/log/utility/setup.hpp>
36 #include <boost/phoenix.hpp>
37 #include <boost/variant.hpp>
38 
39 #include <atomic>
40 #include <cstdlib>
41 #include <iostream>
42 #include <mutex>
43 #include <regex>
44 
45 namespace logger {
46 
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;
53 
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)
57 
58 BOOST_LOG_GLOBAL_LOGGER_DEFAULT(gChannelLogger, ChannelLogger)
59 BOOST_LOG_GLOBAL_LOGGER_DEFAULT(gSeverityLogger, SeverityLogger)
60 
61 // Return last component of path
62 std::string filename(char const* path) {
63  return boost::filesystem::path(path).filename().string();
64 }
65 
66 LogOptions::LogOptions(char const* argv0) {
67  // Log file base_name matches name of program.
68  std::string const base_name =
69  argv0 == nullptr ? std::string("omnisci_server") : filename(argv0);
71  symlink_ = base_name + symlink_;
72  set_options();
73 }
74 
75 boost::filesystem::path LogOptions::full_log_dir() const {
76  return log_dir_.has_root_directory() ? log_dir_ : base_path_ / log_dir_;
77 }
78 
79 po::options_description const& LogOptions::get_options() const {
80  return *options_;
81 }
82 
83 // Typical usage calls either get_options() or parse_command_line() but not both.
84 void LogOptions::parse_command_line(int argc, char const* const* argv) {
85  po::variables_map vm;
86  po::store(
87  po::command_line_parser(argc, argv).options(*options_).allow_unregistered().run(),
88  vm);
89  po::notify(vm); // Sets LogOptions member variables.
90 }
91 
92 // Must be called before init() to take effect.
93 void LogOptions::set_base_path(std::string const& base_path) {
94  base_path_ = base_path;
95 }
96 
97 // May be called to update default values based on updated member variables.
99  options_ = std::make_unique<boost::program_options::options_description>("Logging");
100  std::string const channels = join(ChannelNames, " ");
101  // Filter out DEBUG[1-4] severities from --help options
102  std::string severities;
103  for (auto const& name : SeverityNames) {
104  if (!boost::algorithm::starts_with(name, "DEBUG")) {
105  (severities += (severities.empty() ? "" : " ")) += name;
106  }
107  }
108  options_->add_options()(
109  "log-directory",
110  po::value<boost::filesystem::path>(&log_dir_)->default_value(log_dir_),
111  "Logging directory. May be relative to data directory, or absolute.");
112  options_->add_options()(
113  "log-file-name",
114  po::value<std::string>(&file_name_pattern_)->default_value(file_name_pattern_),
115  "Log file name relative to log-directory.");
116  options_->add_options()("log-symlink",
117  po::value<std::string>(&symlink_)->default_value(symlink_),
118  "Symlink to active log.");
119  options_->add_options()("log-severity",
120  po::value<Severity>(&severity_)->default_value(severity_),
121  ("Log to file severity level: " + severities).c_str());
122  options_->add_options()(
123  "log-severity-clog",
124  po::value<Severity>(&severity_clog_)->default_value(severity_clog_),
125  ("Log to console severity level: " + severities).c_str());
126  options_->add_options()("log-channels",
127  po::value<Channels>(&channels_)->default_value(channels_),
128  ("Log channel debug info: " + channels).c_str());
129  options_->add_options()("log-auto-flush",
130  po::value<bool>(&auto_flush_)->default_value(auto_flush_),
131  "Flush logging buffer to file after each message.");
132  options_->add_options()("log-max-files",
133  po::value<size_t>(&max_files_)->default_value(max_files_),
134  "Maximum number of log files to keep.");
135  options_->add_options()(
136  "log-min-free-space",
137  po::value<size_t>(&min_free_space_)->default_value(min_free_space_),
138  "Minimum number of bytes left on device before oldest log files are deleted.");
139  options_->add_options()("log-rotate-daily",
140  po::value<bool>(&rotate_daily_)->default_value(rotate_daily_),
141  "Start new log files at midnight.");
142  options_->add_options()(
143  "log-rotation-size",
144  po::value<size_t>(&rotation_size_)->default_value(rotation_size_),
145  "Maximum file size in bytes before new log files are started.");
146 }
147 
148 template <typename TAG>
149 std::string replace_braces(std::string const& str, TAG const tag) {
150  constexpr std::regex::flag_type flags = std::regex::ECMAScript | std::regex::optimize;
151  static std::regex const regex(R"(\{SEVERITY\})", flags);
152  if /*constexpr*/ (std::is_same<TAG, Channel>::value) {
153  return std::regex_replace(str, regex, ChannelNames[tag]);
154  } else {
155  return std::regex_replace(str, regex, SeverityNames[tag]);
156  }
157 }
158 
159 // Print decimal value for process_id (14620) instead of hex (0x0000391c)
160 boost::log::attributes::current_process_id::value_type::native_type get_native_process_id(
161  boost::log::value_ref<boost::log::attributes::current_process_id::value_type,
162  tag::process_id> const& pid) {
163  return pid ? pid->native_id() : 0;
164 }
165 
166 template <typename SINK>
167 sinks::text_file_backend::open_handler_type create_or_replace_symlink(
168  boost::weak_ptr<SINK> weak_ptr,
169  std::string&& symlink) {
170  namespace fs = boost::filesystem;
171  return [weak_ptr,
172  symlink = std::move(symlink)](sinks::text_file_backend::stream_type& stream) {
173  if (boost::shared_ptr<SINK> sink = weak_ptr.lock()) {
175  fs::path const& file_name = sink->locked_backend()->get_current_file_name();
176  fs::path const symlink_path = file_name.parent_path() / symlink;
177  fs::remove(symlink_path, ec);
178  if (ec) {
179  stream << filename(__FILE__) << ':' << __LINE__ << ' ' << ec.message() << '\n';
180  }
181  fs::create_symlink(file_name.filename(), symlink_path, ec);
182  if (ec) {
183  stream << filename(__FILE__) << ':' << __LINE__ << ' ' << ec.message() << '\n';
184  }
185  }
186  };
187 }
188 
189 boost::log::formatting_ostream& operator<<(
190  boost::log::formatting_ostream& strm,
191  boost::log::to_log_manip<Channel, tag::channel> const& manip) {
192  return strm << ChannelSymbols[manip.get()];
193 }
194 
195 boost::log::formatting_ostream& operator<<(
196  boost::log::formatting_ostream& strm,
197  boost::log::to_log_manip<Severity, tag::severity> const& manip) {
198  return strm << SeveritySymbols[manip.get()];
199 }
200 
201 template <typename TAG, typename SINK>
202 void set_formatter(SINK& sink) {
203  if /*constexpr*/ (std::is_same<TAG, Channel>::value) {
204  sink->set_formatter(
205  expr::stream << expr::format_date_time<boost::posix_time::ptime>(
206  "TimeStamp", "%Y-%m-%dT%H:%M:%S.%f")
207  << ' ' << channel << ' '
208  << boost::phoenix::bind(&get_native_process_id, process_id.or_none())
209  << ' ' << expr::smessage);
210  } else {
211  sink->set_formatter(
212  expr::stream << expr::format_date_time<boost::posix_time::ptime>(
213  "TimeStamp", "%Y-%m-%dT%H:%M:%S.%f")
214  << ' ' << severity << ' '
215  << boost::phoenix::bind(&get_native_process_id, process_id.or_none())
216  << ' ' << expr::smessage);
217  }
218 }
219 
220 template <typename FILE_SINK, typename TAG>
221 boost::shared_ptr<FILE_SINK> make_sink(LogOptions const& log_opts,
222  boost::filesystem::path const& full_log_dir,
223  TAG const tag) {
224  auto sink = boost::make_shared<FILE_SINK>(
225  keywords::file_name =
226  full_log_dir / replace_braces(log_opts.file_name_pattern_, tag),
227  keywords::auto_flush = log_opts.auto_flush_,
228  keywords::rotation_size = log_opts.rotation_size_);
229  if /*constexpr*/ (std::is_same<TAG, Channel>::value) {
230  sink->set_filter(channel == static_cast<Channel>(tag));
231  set_formatter<Channel>(sink);
232  } else {
233  // INFO sink logs all other levels. Other sinks only log at their level or higher.
234  Severity const min_filter_level = static_cast<Severity>(tag) == Severity::INFO
235  ? log_opts.severity_
236  : static_cast<Severity>(tag);
237  sink->set_filter(min_filter_level <= severity);
238  set_formatter<Severity>(sink);
239  }
240  typename FILE_SINK::locked_backend_ptr backend = sink->locked_backend();
241  if (log_opts.rotate_daily_) {
242  backend->set_time_based_rotation(sinks::file::rotation_at_time_point(0, 0, 0));
243  }
244  backend->set_file_collector(
245  sinks::file::make_collector(keywords::target = full_log_dir,
246  keywords::max_files = log_opts.max_files_,
247  keywords::min_free_space = log_opts.min_free_space_));
248  backend->set_open_handler(create_or_replace_symlink(
249  boost::weak_ptr<FILE_SINK>(sink), replace_braces(log_opts.symlink_, tag)));
250  backend->scan_for_files();
251  return sink;
252 }
253 
254 // Pointer to function to optionally call on LOG(FATAL).
255 std::atomic<FatalFunc> g_fatal_func{nullptr};
256 std::once_flag g_fatal_func_flag;
257 
258 using ClogSync = sinks::synchronous_sink<sinks::text_ostream_backend>;
259 using FileSync = sinks::synchronous_sink<sinks::text_file_backend>;
260 
261 template <typename CONSOLE_SINK>
262 boost::shared_ptr<CONSOLE_SINK> make_sink(LogOptions const& log_opts) {
263  auto sink = boost::make_shared<CONSOLE_SINK>();
264  boost::shared_ptr<std::ostream> clog(&std::clog, boost::null_deleter());
265  sink->locked_backend()->add_stream(clog);
266  sink->set_filter(log_opts.severity_clog_ <= severity);
267  set_formatter<Severity>(sink);
268  return sink;
269 }
270 
271 // Locking/atomicity not needed for g_any_active_channels or g_min_active_severity
272 // as they are modifed by init() once.
275 
276 void init(LogOptions const& log_opts) {
277  boost::shared_ptr<boost::log::core> core = boost::log::core::get();
278  // boost::log::add_common_attributes(); // LineID TimeStamp ProcessID ThreadID
279  core->add_global_attribute("TimeStamp", attr::local_clock());
280  core->add_global_attribute("ProcessID", attr::current_process_id());
281  if (0 < log_opts.max_files_) {
282  boost::filesystem::path const full_log_dir = log_opts.full_log_dir();
283  bool const log_dir_was_created = boost::filesystem::create_directory(full_log_dir);
284  // Don't create separate log sinks for anything less than Severity::INFO.
285  Severity const min_sink_level = std::max(Severity::INFO, log_opts.severity_);
286  for (int i = min_sink_level; i < Severity::_NSEVERITIES; ++i) {
287  Severity const level = static_cast<Severity>(i);
288  core->add_sink(make_sink<FileSync>(log_opts, full_log_dir, level));
289  }
291  if (log_dir_was_created) {
292  LOG(INFO) << "Log directory(" << full_log_dir.native() << ") created.";
293  }
294  for (auto const channel : log_opts.channels_) {
295  core->add_sink(make_sink<FileSync>(log_opts, full_log_dir, channel));
296  }
297  g_any_active_channels = !log_opts.channels_.empty();
298  }
299  core->add_sink(make_sink<ClogSync>(log_opts));
301 }
302 
303 void set_once_fatal_func(FatalFunc fatal_func) {
304  if (g_fatal_func.exchange(fatal_func)) {
305  throw std::runtime_error(
306  "logger::set_once_fatal_func() should not be called more than once.");
307  }
308 }
309 
310 void shutdown() {
311  boost::log::core::get()->remove_all_sinks();
312 }
313 
314 // Used by boost::program_options when parsing enum Channel.
315 std::istream& operator>>(std::istream& in, Channels& channels) {
316  std::string line;
317  std::getline(in, line);
318  unquote(line);
319  std::regex const rex(R"(\w+)");
320  using TokenItr = std::regex_token_iterator<std::string::iterator>;
321  TokenItr const end;
322  for (TokenItr tok(line.begin(), line.end(), rex); tok != end; ++tok) {
323  auto itr = std::find(ChannelNames.cbegin(), ChannelNames.cend(), *tok);
324  if (itr == ChannelNames.cend()) {
325  in.setstate(std::ios_base::failbit);
326  break;
327  } else {
328  channels.emplace(static_cast<Channel>(itr - ChannelNames.cbegin()));
329  }
330  }
331  return in;
332 }
333 
334 // Used by boost::program_options when stringifying Channels.
335 std::ostream& operator<<(std::ostream& out, Channels const& channels) {
336  int i = 0;
337  for (auto const channel : channels) {
338  out << (i++ ? " " : "") << ChannelNames.at(channel);
339  }
340  return out;
341 }
342 
343 // Used by boost::program_options when parsing enum Severity.
344 std::istream& operator>>(std::istream& in, Severity& sev) {
345  std::string token;
346  in >> token;
347  unquote(token);
348  auto itr = std::find(SeverityNames.cbegin(), SeverityNames.cend(), token);
349  if (itr == SeverityNames.cend()) {
350  in.setstate(std::ios_base::failbit);
351  } else {
352  sev = static_cast<Severity>(itr - SeverityNames.cbegin());
353  }
354  return in;
355 }
356 
357 // Used by boost::program_options when stringifying enum Severity.
358 std::ostream& operator<<(std::ostream& out, Severity const& sev) {
359  return out << SeverityNames.at(sev);
360 }
361 
363  : is_channel_(true)
364  , enum_value_(channel)
365  , record_(std::make_unique<boost::log::record>(
366  gChannelLogger::get().open_record(boost::log::keywords::channel = channel))) {
367  if (*record_) {
368  stream_ = std::make_unique<boost::log::record_ostream>(*record_);
369  }
370 }
371 
373  : is_channel_(false)
374  , enum_value_(severity)
375  , record_(std::make_unique<boost::log::record>(gSeverityLogger::get().open_record(
376  boost::log::keywords::severity = severity))) {
377  if (*record_) {
378  stream_ = std::make_unique<boost::log::record_ostream>(*record_);
379  }
380 }
381 
383  if (stream_) {
384  if (is_channel_) {
385  gChannelLogger::get().push_record(boost::move(stream_->get_record()));
386  } else {
387  gSeverityLogger::get().push_record(boost::move(stream_->get_record()));
388  }
389  }
390  if (!is_channel_ && static_cast<Severity>(enum_value_) == Severity::FATAL) {
391  if (FatalFunc fatal_func = g_fatal_func.load()) {
392  // set_once_fatal_func() prevents race condition.
393  // Exceptions thrown by (*fatal_func)() are propagated here.
394  std::call_once(g_fatal_func_flag, *fatal_func);
395  }
396  abort();
397  }
398 }
399 
400 Logger::operator bool() const {
401  return static_cast<bool>(stream_);
402 }
403 
404 boost::log::record_ostream& Logger::stream(char const* file, int line) {
405  return *stream_ << thread_id() << ' ' << filename(file) << ':' << line << ' ';
406 }
407 
408 // DebugTimer-related classes and functions.
409 using Clock = std::chrono::steady_clock;
410 
411 class DurationTree;
412 
413 class Duration {
415  Clock::time_point const start_;
416  Clock::time_point stop_;
417 
418  public:
419  int const depth_;
421  char const* const file_;
422  int const line_;
423  char const* const name_;
424 
425  Duration(DurationTree* duration_tree,
426  int depth,
427  Severity severity,
428  char const* file,
429  int line,
430  char const* name)
431  : duration_tree_(duration_tree)
432  , start_(Clock::now())
433  , depth_(depth)
434  , severity_(severity)
435  , file_(file)
436  , line_(line)
437  , name_(name) {}
438  bool stop();
439  // Start time relative to parent DurationTree::start_.
440  template <typename Units = std::chrono::milliseconds>
441  typename Units::rep relative_start_time() const;
442  // Duration value = stop_ - start_.
443  template <typename Units = std::chrono::milliseconds>
444  typename Units::rep value() const;
445 };
446 
447 using DurationTreeNode = boost::variant<Duration, DurationTree&>;
448 using DurationTreeNodes = std::deque<DurationTreeNode>;
449 
452  int current_depth_; //< Depth of next DurationTreeNode.
453 
454  public:
455  int const depth_; //< Depth of tree within parent tree, 0 for root tree.
456  Clock::time_point const start_;
458  DurationTree(ThreadId thread_id, int start_depth)
459  // Add +1 to current_depth_ for non-root DurationTrees for extra indentation.
460  : current_depth_(start_depth + bool(start_depth))
461  , depth_(start_depth)
462  , start_(Clock::now())
463  , thread_id_(thread_id) {}
464  void pushDurationTree(DurationTree& duration_tree) {
465  durations_.emplace_back(duration_tree);
466  }
467  const Duration& rootDuration() const {
468  CHECK(!durations_.empty());
469  return boost::get<Duration>(durations_.front());
470  }
471  int currentDepth() const { return current_depth_; }
473  DurationTreeNodes const& durations() const { return durations_; }
474  template <typename... Ts>
476  durations_.emplace_back(Duration(this, current_depth_++, std::forward<Ts>(args)...));
477  return boost::get<Duration>(&durations_.back());
478  }
479 };
480 
484  stop_ = Clock::now();
486  return depth_ == 0;
487 }
488 
489 template <typename Units>
490 typename Units::rep Duration::relative_start_time() const {
491  return std::chrono::duration_cast<Units>(start_ - duration_tree_->start_).count();
492 }
493 
494 template <typename Units>
495 typename Units::rep Duration::value() const {
496  return std::chrono::duration_cast<Units>(stop_ - start_).count();
497 }
498 
499 struct GetDepth : boost::static_visitor<int> {
500  int operator()(Duration const& duration) const { return duration.depth_; }
501  int operator()(DurationTree const& duration_tree) const { return duration_tree.depth_; }
502 };
503 
504 using DurationTreeMap = std::unordered_map<ThreadId, std::unique_ptr<DurationTree>>;
505 
508 std::atomic<ThreadId> g_next_thread_id{0};
509 ThreadId thread_local const g_thread_id = g_next_thread_id++;
510 
511 template <typename... Ts>
512 Duration* newDuration(Severity severity, Ts&&... args) {
513  if (g_enable_debug_timer) {
514  std::lock_guard<std::mutex> lock_guard(g_duration_tree_map_mutex);
515  auto& duration_tree_ptr = g_duration_tree_map[g_thread_id];
516  if (!duration_tree_ptr) {
517  duration_tree_ptr = std::make_unique<DurationTree>(g_thread_id, 0);
518  }
519  return duration_tree_ptr->newDuration(severity, std::forward<Ts>(args)...);
520  }
521  return nullptr; // Inactive - don't measure or report timing.
522 }
523 
524 std::ostream& operator<<(std::ostream& os, Duration const& duration) {
525  return os << std::setw(2 * duration.depth_) << ' ' << duration.value() << "ms start("
526  << duration.relative_start_time() << "ms) " << duration.name_ << ' '
527  << filename(duration.file_) << ':' << duration.line_;
528 }
529 
530 std::ostream& operator<<(std::ostream& os, DurationTree const& duration_tree) {
531  os << std::setw(2 * duration_tree.depth_) << ' ' << "New thread("
532  << duration_tree.thread_id_ << ')';
533  for (auto const& duration_tree_node : duration_tree.durations()) {
534  os << '\n' << duration_tree_node;
535  }
536  return os << '\n'
537  << std::setw(2 * duration_tree.depth_) << ' ' << "End thread("
538  << duration_tree.thread_id_ << ')';
539 }
540 
541 // Only called by logAndEraseDurationTree() on root tree
542 boost::log::record_ostream& operator<<(boost::log::record_ostream& os,
543  DurationTreeMap::const_reference kv_pair) {
544  auto itr = kv_pair.second->durations().cbegin();
545  auto const end = kv_pair.second->durations().cend();
546  auto const& root_duration = boost::get<Duration>(*itr);
547  os << "DEBUG_TIMER thread_id(" << kv_pair.first << ")\n"
548  << root_duration.value() << "ms total duration for " << root_duration.name_;
549  for (++itr; itr != end; ++itr) {
550  os << '\n' << *itr;
551  }
552  return os;
553 }
554 
555 // Encode DurationTree into json.
556 // DurationTrees encode parent/child relationships using a combination
557 // of ordered descendents, and an int depth member value for each node.
558 // Direct-child nodes are those which:
559 // * do not come after a node of depth <= parent_depth
560 // * have depth == parent_depth + 1
561 class JsonEncoder : boost::static_visitor<rapidjson::Value> {
562  std::shared_ptr<rapidjson::Document> doc_;
563  rapidjson::Document::AllocatorType& alloc_;
564  // Iterators are used to determine children when visiting a Duration node.
565  DurationTreeNodes::const_iterator begin_;
566  DurationTreeNodes::const_iterator end_;
567 
568  JsonEncoder(JsonEncoder& json_encoder,
569  DurationTreeNodes::const_iterator begin,
570  DurationTreeNodes::const_iterator end)
571  : doc_(json_encoder.doc_), alloc_(doc_->GetAllocator()), begin_(begin), end_(end) {}
572 
573  public:
575  : doc_(std::make_shared<rapidjson::Document>(rapidjson::kObjectType))
576  , alloc_(doc_->GetAllocator()) {}
577  rapidjson::Value operator()(Duration const& duration) {
578  rapidjson::Value retval(rapidjson::kObjectType);
579  retval.AddMember("type", "duration", alloc_);
580  retval.AddMember("duration_ms", rapidjson::Value(duration.value()), alloc_);
581  retval.AddMember(
582  "start_ms", rapidjson::Value(duration.relative_start_time()), alloc_);
583  retval.AddMember("name", rapidjson::StringRef(duration.name_), alloc_);
584  retval.AddMember("file", filename(duration.file_), alloc_);
585  retval.AddMember("line", rapidjson::Value(duration.line_), alloc_);
586  retval.AddMember("children", childNodes(duration.depth_), alloc_);
587  return retval;
588  }
589  rapidjson::Value operator()(DurationTree const& duration_tree) {
590  begin_ = duration_tree.durations().cbegin();
591  end_ = duration_tree.durations().cend();
592  rapidjson::Value retval(rapidjson::kObjectType);
593  retval.AddMember("type", "duration_tree", alloc_);
594  retval.AddMember("thread_id", to_string(duration_tree.thread_id_), alloc_);
595  retval.AddMember("children", childNodes(duration_tree.depth_), alloc_);
596  return retval;
597  }
598  rapidjson::Value childNodes(int const parent_depth) {
599  GetDepth const get_depth;
600  rapidjson::Value children(rapidjson::kArrayType);
601  for (auto itr = begin_; itr != end_; ++itr) {
602  int const depth = apply_visitor(get_depth, *itr);
603  if (depth <= parent_depth) {
604  break;
605  }
606  if (depth == parent_depth + 1) {
607  JsonEncoder json_encoder(*this, std::next(itr), end_);
608  children.PushBack(apply_visitor(json_encoder, *itr), alloc_);
609  }
610  }
611  return children;
612  }
613  // The root Duration is the "timer" node in the top level debug json object.
614  // Only root Duration has overall total_duration_ms.
615  rapidjson::Value timer(DurationTreeMap::const_reference kv_pair) {
616  begin_ = kv_pair.second->durations().cbegin();
617  end_ = kv_pair.second->durations().cend();
618  rapidjson::Value retval(rapidjson::kObjectType);
619  if (begin_ != end_) {
620  auto const& root_duration = boost::get<Duration>(*(begin_++));
621  retval.AddMember("type", "root", alloc_);
622  retval.AddMember("thread_id", to_string(kv_pair.first), alloc_);
623  retval.AddMember(
624  "total_duration_ms", rapidjson::Value(root_duration.value()), alloc_);
625  retval.AddMember("name", rapidjson::StringRef(root_duration.name_), alloc_);
626  retval.AddMember("children", childNodes(0), alloc_);
627  }
628  return retval;
629  }
630  // Assumes *doc_ is empty.
631  std::string str(DurationTreeMap::const_reference kv_pair) {
632  doc_->AddMember("timer", timer(kv_pair), alloc_);
633  rapidjson::StringBuffer buffer;
634  rapidjson::Writer<rapidjson::StringBuffer> writer(buffer);
635  doc_->Accept(writer);
636  return {buffer.GetString(), buffer.GetSize()};
637  }
638 };
639 
641 struct EraseDurationTrees : boost::static_visitor<> {
642  void operator()(DurationTreeMap::const_iterator const& itr) const {
643  for (auto const& duration_tree_node : itr->second->durations()) {
644  apply_visitor(*this, duration_tree_node);
645  }
646  g_duration_tree_map.erase(itr);
647  }
648  void operator()(Duration const&) const {}
649  void operator()(DurationTree const& duration_tree) const {
650  for (auto const& duration_tree_node : duration_tree.durations()) {
651  apply_visitor(*this, duration_tree_node);
652  }
653  g_duration_tree_map.erase(duration_tree.thread_id_);
654  }
655 };
656 
657 void logAndEraseDurationTree(std::string* json_str) {
658  std::lock_guard<std::mutex> lock_guard(g_duration_tree_map_mutex);
659  DurationTreeMap::const_iterator const itr = g_duration_tree_map.find(g_thread_id);
660  CHECK(itr != g_duration_tree_map.cend());
661  auto const& root_duration = itr->second->rootDuration();
662  if (auto log = Logger(root_duration.severity_)) {
663  log.stream(root_duration.file_, root_duration.line_) << *itr;
664  }
665  if (json_str) {
666  JsonEncoder json_encoder;
667  *json_str = json_encoder.str(*itr);
668  }
669  EraseDurationTrees erase_duration_trees;
670  erase_duration_trees(itr);
671 }
672 
673 DebugTimer::DebugTimer(Severity severity, char const* file, int line, char const* name)
674  : duration_(newDuration(severity, file, line, name)) {}
675 
677  stop();
678 }
679 
681  if (duration_) {
682  if (duration_->stop()) {
683  logAndEraseDurationTree(nullptr);
684  }
685  duration_ = nullptr;
686  }
687 }
688 
690  std::string json_str;
691  if (duration_) {
692  if (duration_->stop()) {
693  logAndEraseDurationTree(&json_str);
694  }
695  duration_ = nullptr;
696  }
697  return json_str;
698 }
699 
702 void debug_timer_new_thread(ThreadId parent_thread_id) {
703  if (g_enable_debug_timer) {
704  std::lock_guard<std::mutex> lock_guard(g_duration_tree_map_mutex);
705  auto parent_itr = g_duration_tree_map.find(parent_thread_id);
706  CHECK(parent_itr != g_duration_tree_map.end());
707  auto const current_depth = parent_itr->second->currentDepth();
708  auto& duration_tree_ptr = g_duration_tree_map[g_thread_id];
709  CHECK(!duration_tree_ptr);
710  duration_tree_ptr = std::make_unique<DurationTree>(g_thread_id, current_depth + 1);
711  parent_itr->second->pushDurationTree(*duration_tree_ptr);
712  }
713 }
714 
716  return g_thread_id;
717 }
718 
719 } // namespace logger
720 
721 #endif // #ifndef __CUDACC__
std::istream & operator>>(std::istream &in, Channels &channels)
Definition: Logger.cpp:315
DurationTreeNodes::const_iterator end_
Definition: Logger.cpp:566
void pushDurationTree(DurationTree &duration_tree)
Definition: Logger.cpp:464
void debug_timer_new_thread(ThreadId parent_thread_id)
Definition: Logger.cpp:702
std::unique_ptr< boost::program_options::options_description > options_
Definition: Logger.h:110
int const enum_value_
Definition: Logger.h:159
std::string filename(char const *path)
Definition: Logger.cpp:62
size_t min_free_space_
Definition: Logger.h:123
std::unordered_map< ThreadId, std::unique_ptr< DurationTree >> DurationTreeMap
Definition: Logger.cpp:504
std::string replace_braces(std::string const &str, TAG const tag)
Definition: Logger.cpp:149
std::set< Channel > Channels
Definition: Logger.h:103
std::string stopAndGetJson()
Definition: Logger.cpp:689
std::mutex g_duration_tree_map_mutex
Definition: Logger.cpp:506
boost::log::sources::channel_logger_mt< Channel > ChannelLogger
Definition: Logger.h:150
void set_formatter(SINK &sink)
Definition: Logger.cpp:202
std::unique_ptr< boost::log::record > record_
Definition: Logger.h:161
LogOptions(char const *argv0)
Definition: Logger.cpp:66
JsonEncoder(JsonEncoder &json_encoder, DurationTreeNodes::const_iterator begin, DurationTreeNodes::const_iterator end)
Definition: Logger.cpp:568
sinks::text_file_backend::open_handler_type create_or_replace_symlink(boost::weak_ptr< SINK > weak_ptr, std::string &&symlink)
Definition: Logger.cpp:167
std::once_flag g_fatal_func_flag
Definition: Logger.cpp:256
void operator()(DurationTreeMap::const_iterator const &itr) const
Definition: Logger.cpp:642
std::string base_path_
Definition: Logger.h:107
#define LOG(tag)
Definition: Logger.h:188
Clock::time_point const start_
Definition: Logger.cpp:415
Duration(DurationTree *duration_tree, int depth, Severity severity, char const *file, int line, char const *name)
Definition: Logger.cpp:425
bool g_enable_debug_timer
Definition: Logger.cpp:17
void operator()(Duration const &) const
Definition: Logger.cpp:648
Channel
Definition: Logger.h:61
const std::string json_str(const rapidjson::Value &obj) noexcept
Definition: JsonAccessors.h:44
DurationTreeNodes durations_
Definition: Logger.cpp:451
std::string join(T const &container, std::string const &delim)
void operator()(DurationTree const &duration_tree) const
Definition: Logger.cpp:649
Units::rep relative_start_time() const
Definition: Logger.cpp:490
Clock::time_point const start_
Definition: Logger.cpp:456
Duration * duration_
Definition: Logger.h:296
rapidjson::Value operator()(Duration const &duration)
Definition: Logger.cpp:577
Duration * newDuration(Severity severity, Ts &&...args)
Definition: Logger.cpp:512
Depth-first search and erase all DurationTrees. Not thread-safe.
Definition: Logger.cpp:641
DurationTreeNodes const & durations() const
Definition: Logger.cpp:473
rapidjson::Value childNodes(int const parent_depth)
Definition: Logger.cpp:598
int currentDepth() const
Definition: Logger.cpp:471
void set_once_fatal_func(FatalFunc fatal_func)
Definition: Logger.cpp:303
std::string to_string(char const *&&v)
sinks::synchronous_sink< sinks::text_ostream_backend > ClogSync
Definition: Logger.cpp:258
void(*)() noexcept FatalFunc
Definition: Logger.h:147
boost::program_options::options_description const & get_options() const
Definition: Logger.cpp:79
char const *const name_
Definition: Logger.cpp:423
int const line_
Definition: Logger.cpp:422
constexpr std::array< char, 8 > SeveritySymbols
Definition: Logger.h:94
Units::rep value() const
Definition: Logger.cpp:495
Channels channels_
Definition: Logger.h:120
bool const is_channel_
Definition: Logger.h:158
DurationTreeNodes::const_iterator begin_
Definition: Logger.cpp:565
constexpr std::array< char, 2 > ChannelSymbols
Definition: Logger.h:65
CHECK(cgen_state)
int const depth_
Definition: Logger.cpp:419
void logAndEraseDurationTree(std::string *json_str)
Definition: Logger.cpp:657
sinks::synchronous_sink< sinks::text_file_backend > FileSync
Definition: Logger.cpp:259
rapidjson::Value operator()(DurationTree const &duration_tree)
Definition: Logger.cpp:589
void init(LogOptions const &log_opts)
Definition: Logger.cpp:276
std::deque< DurationTreeNode > DurationTreeNodes
Definition: Logger.cpp:448
Severity g_min_active_severity
Definition: Logger.cpp:274
std::atomic< FatalFunc > g_fatal_func
Definition: Logger.cpp:255
const int8_t const int64_t const uint64_t const int32_t const int64_t int64_t uint32_t const int64_t int32_t * error_code
DebugTimer(Severity, char const *file, int line, char const *name)
Definition: Logger.cpp:673
int operator()(Duration const &duration) const
Definition: Logger.cpp:500
ThreadId thread_local const g_thread_id
Definition: Logger.cpp:509
boost::shared_ptr< FILE_SINK > make_sink(LogOptions const &log_opts, boost::filesystem::path const &full_log_dir, TAG const tag)
Definition: Logger.cpp:221
std::atomic< ThreadId > g_next_thread_id
Definition: Logger.cpp:508
bool rotate_daily_
Definition: Logger.h:124
DurationTree *const duration_tree_
Definition: Logger.cpp:414
bool g_enable_smem_group_by true
std::string symlink_
Definition: Logger.h:117
ThreadId const thread_id_
Definition: Logger.cpp:457
std::unique_ptr< boost::log::record_ostream > stream_
Definition: Logger.h:162
Severity
Definition: Logger.h:73
boost::log::formatting_ostream & operator<<(boost::log::formatting_ostream &strm, boost::log::to_log_manip< Channel, tag::channel > const &manip)
Definition: Logger.cpp:189
void shutdown()
Definition: Logger.cpp:310
constexpr std::array< char const *, 8 > SeverityNames
Definition: Logger.h:85
rapidjson::Value timer(DurationTreeMap::const_reference kv_pair)
Definition: Logger.cpp:615
uint64_t ThreadId
Definition: Logger.h:306
const Duration & rootDuration() const
Definition: Logger.cpp:467
Severity severity_
Definition: Logger.h:118
constexpr std::array< char const *, 2 > ChannelNames
Definition: Logger.h:63
std::string str(DurationTreeMap::const_reference kv_pair)
Definition: Logger.cpp:631
bool g_any_active_channels
Definition: Logger.cpp:273
ThreadId thread_id()
Definition: Logger.cpp:715
boost::log::sources::severity_logger_mt< Severity > SeverityLogger
Definition: Logger.h:153
std::string file_name_pattern_
Definition: Logger.h:116
bool g_enable_watchdog false
Definition: Execute.cpp:74
size_t rotation_size_
Definition: Logger.h:125
int operator()(DurationTree const &duration_tree) const
Definition: Logger.cpp:501
void set_base_path(std::string const &base_path)
Definition: Logger.cpp:93
DurationTreeMap g_duration_tree_map
Definition: Logger.cpp:507
boost::filesystem::path full_log_dir() const
Definition: Logger.cpp:75
char const *const file_
Definition: Logger.cpp:421
int const depth_
Definition: Logger.cpp:455
std::chrono::steady_clock Clock
Definition: Logger.cpp:409
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)
Definition: Logger.cpp:160
size_t max_files_
Definition: Logger.h:122
Logger(Channel)
Definition: Logger.cpp:362
bool unquote(std::string &str)
const int8_t const int64_t const uint64_t const int32_t const int64_t int64_t ** out
std::shared_ptr< rapidjson::Document > doc_
Definition: Logger.cpp:562
boost::variant< Duration, DurationTree & > DurationTreeNode
Definition: Logger.cpp:447
Severity severity_clog_
Definition: Logger.h:119
boost::filesystem::path log_dir_
Definition: Logger.h:114
void set_options()
Definition: Logger.cpp:98
Duration * newDuration(Ts &&...args)
Definition: Logger.cpp:475
Severity const severity_
Definition: Logger.cpp:420
rapidjson::Document::AllocatorType & alloc_
Definition: Logger.cpp:563
Clock::time_point stop_
Definition: Logger.cpp:416
boost::log::record_ostream & stream(char const *file, int line)
Definition: Logger.cpp:404
void parse_command_line(int, char const *const *)
Definition: Logger.cpp:84