OmniSciDB  85c2d10cdc
 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 
23 #include <rapidjson/document.h>
24 #include <rapidjson/stringbuffer.h>
25 #include <rapidjson/writer.h>
26 
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>
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 =
101  std::accumulate(ChannelNames.cbegin() + 1,
102  ChannelNames.cend(),
103  std::string(ChannelNames.front()),
104  [](auto a, auto channel) { return a + ' ' + channel; });
105  // Filter out DEBUG[1-4] severities from --help options
106  std::string severities;
107  for (auto const& name : SeverityNames) {
108  if (!boost::algorithm::starts_with(name, "DEBUG")) {
109  (severities += (severities.empty() ? "" : " ")) += name;
110  }
111  }
112  options_->add_options()(
113  "log-directory",
114  po::value<boost::filesystem::path>(&log_dir_)->default_value(log_dir_),
115  "Logging directory. May be relative to data directory, or absolute.");
116  options_->add_options()(
117  "log-file-name",
118  po::value<std::string>(&file_name_pattern_)->default_value(file_name_pattern_),
119  "Log file name relative to log-directory.");
120  options_->add_options()("log-symlink",
121  po::value<std::string>(&symlink_)->default_value(symlink_),
122  "Symlink to active log.");
123  options_->add_options()("log-severity",
124  po::value<Severity>(&severity_)->default_value(severity_),
125  ("Log to file severity level: " + severities).c_str());
126  options_->add_options()(
127  "log-severity-clog",
128  po::value<Severity>(&severity_clog_)->default_value(severity_clog_),
129  ("Log to console severity level: " + severities).c_str());
130  options_->add_options()("log-channels",
131  po::value<Channels>(&channels_)->default_value(channels_),
132  ("Log channel debug info: " + channels).c_str());
133  options_->add_options()("log-auto-flush",
134  po::value<bool>(&auto_flush_)->default_value(auto_flush_),
135  "Flush logging buffer to file after each message.");
136  options_->add_options()("log-max-files",
137  po::value<size_t>(&max_files_)->default_value(max_files_),
138  "Maximum number of log files to keep.");
139  options_->add_options()(
140  "log-min-free-space",
141  po::value<size_t>(&min_free_space_)->default_value(min_free_space_),
142  "Minimum number of bytes left on device before oldest log files are deleted.");
143  options_->add_options()("log-rotate-daily",
144  po::value<bool>(&rotate_daily_)->default_value(rotate_daily_),
145  "Start new log files at midnight.");
146  options_->add_options()(
147  "log-rotation-size",
148  po::value<size_t>(&rotation_size_)->default_value(rotation_size_),
149  "Maximum file size in bytes before new log files are started.");
150 }
151 
152 template <typename TAG>
153 std::string replace_braces(std::string const& str, TAG const 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 /*constexpr*/ (std::is_same<TAG, Channel>::value) {
157  return std::regex_replace(str, regex, ChannelNames[tag]);
158  } else {
159  return std::regex_replace(str, regex, SeverityNames[tag]);
160  }
161 }
162 
163 // Print decimal value for process_id (14620) instead of hex (0x0000391c)
164 boost::log::attributes::current_process_id::value_type::native_type get_native_process_id(
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;
168 }
169 
170 template <typename SINK>
171 sinks::text_file_backend::open_handler_type create_or_replace_symlink(
172  boost::weak_ptr<SINK> weak_ptr,
173  std::string&& symlink) {
174  namespace fs = boost::filesystem;
175  return [weak_ptr,
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);
182  if (ec) {
183  stream << filename(__FILE__) << ':' << __LINE__ << ' ' << ec.message() << '\n';
184  }
185  fs::create_symlink(file_name.filename(), symlink_path, ec);
186  if (ec) {
187  stream << filename(__FILE__) << ':' << __LINE__ << ' ' << ec.message() << '\n';
188  }
189  }
190  };
191 }
192 
193 boost::log::formatting_ostream& operator<<(
194  boost::log::formatting_ostream& strm,
195  boost::log::to_log_manip<Channel, tag::channel> const& manip) {
196  return strm << ChannelSymbols[manip.get()];
197 }
198 
199 boost::log::formatting_ostream& operator<<(
200  boost::log::formatting_ostream& strm,
201  boost::log::to_log_manip<Severity, tag::severity> const& manip) {
202  return strm << SeveritySymbols[manip.get()];
203 }
204 
205 template <typename TAG, typename SINK>
206 void set_formatter(SINK& sink) {
207  if /*constexpr*/ (std::is_same<TAG, Channel>::value) {
208  sink->set_formatter(
209  expr::stream << expr::format_date_time<boost::posix_time::ptime>(
210  "TimeStamp", "%Y-%m-%dT%H:%M:%S.%f")
211  << ' ' << channel << ' '
212  << boost::phoenix::bind(&get_native_process_id, process_id.or_none())
213  << ' ' << expr::smessage);
214  } else {
215  sink->set_formatter(
216  expr::stream << expr::format_date_time<boost::posix_time::ptime>(
217  "TimeStamp", "%Y-%m-%dT%H:%M:%S.%f")
218  << ' ' << severity << ' '
219  << boost::phoenix::bind(&get_native_process_id, process_id.or_none())
220  << ' ' << expr::smessage);
221  }
222 }
223 
224 template <typename FILE_SINK, typename TAG>
225 boost::shared_ptr<FILE_SINK> make_sink(LogOptions const& log_opts,
226  boost::filesystem::path const& full_log_dir,
227  TAG const tag) {
228  auto sink = boost::make_shared<FILE_SINK>(
229  keywords::file_name =
230  full_log_dir / replace_braces(log_opts.file_name_pattern_, tag),
231  keywords::auto_flush = log_opts.auto_flush_,
232  keywords::rotation_size = log_opts.rotation_size_);
233  if /*constexpr*/ (std::is_same<TAG, Channel>::value) {
234  sink->set_filter(channel == static_cast<Channel>(tag));
235  set_formatter<Channel>(sink);
236  } else {
237  // INFO sink logs all other levels. Other sinks only log at their level or higher.
238  Severity const min_filter_level = static_cast<Severity>(tag) == Severity::INFO
239  ? log_opts.severity_
240  : static_cast<Severity>(tag);
241  sink->set_filter(min_filter_level <= severity);
242  set_formatter<Severity>(sink);
243  }
244  typename FILE_SINK::locked_backend_ptr backend = sink->locked_backend();
245  if (log_opts.rotate_daily_) {
246  backend->set_time_based_rotation(sinks::file::rotation_at_time_point(0, 0, 0));
247  }
248  backend->set_file_collector(
249  sinks::file::make_collector(keywords::target = full_log_dir,
250  keywords::max_files = log_opts.max_files_,
251  keywords::min_free_space = log_opts.min_free_space_));
252  backend->set_open_handler(create_or_replace_symlink(
253  boost::weak_ptr<FILE_SINK>(sink), replace_braces(log_opts.symlink_, tag)));
254  backend->scan_for_files();
255  return sink;
256 }
257 
258 // Pointer to function to optionally call on LOG(FATAL).
259 std::atomic<FatalFunc> g_fatal_func{nullptr};
260 std::once_flag g_fatal_func_flag;
261 
262 using ClogSync = sinks::synchronous_sink<sinks::text_ostream_backend>;
263 using FileSync = sinks::synchronous_sink<sinks::text_file_backend>;
264 
265 template <typename CONSOLE_SINK>
266 boost::shared_ptr<CONSOLE_SINK> make_sink(LogOptions const& log_opts) {
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);
270  sink->set_filter(log_opts.severity_clog_ <= severity);
271  set_formatter<Severity>(sink);
272  return sink;
273 }
274 
275 // Locking/atomicity not needed for g_any_active_channels or g_min_active_severity
276 // as they are modifed by init() once.
279 
280 void init(LogOptions const& log_opts) {
281  boost::shared_ptr<boost::log::core> core = boost::log::core::get();
282  // boost::log::add_common_attributes(); // LineID TimeStamp ProcessID ThreadID
283  core->add_global_attribute("TimeStamp", attr::local_clock());
284  core->add_global_attribute("ProcessID", attr::current_process_id());
285  if (0 < log_opts.max_files_) {
286  boost::filesystem::path const full_log_dir = log_opts.full_log_dir();
287  bool const log_dir_was_created = boost::filesystem::create_directory(full_log_dir);
288  // Don't create separate log sinks for anything less than Severity::INFO.
289  Severity const min_sink_level = std::max(Severity::INFO, log_opts.severity_);
290  for (int i = min_sink_level; i < Severity::_NSEVERITIES; ++i) {
291  Severity const level = static_cast<Severity>(i);
292  core->add_sink(make_sink<FileSync>(log_opts, full_log_dir, level));
293  }
295  if (log_dir_was_created) {
296  LOG(INFO) << "Log directory(" << full_log_dir.native() << ") created.";
297  }
298  for (auto const channel : log_opts.channels_) {
299  core->add_sink(make_sink<FileSync>(log_opts, full_log_dir, channel));
300  }
301  g_any_active_channels = !log_opts.channels_.empty();
302  }
303  core->add_sink(make_sink<ClogSync>(log_opts));
305 }
306 
307 void set_once_fatal_func(FatalFunc fatal_func) {
308  if (g_fatal_func.exchange(fatal_func)) {
309  throw std::runtime_error(
310  "logger::set_once_fatal_func() should not be called more than once.");
311  }
312 }
313 
314 void shutdown() {
315  static std::once_flag logger_flag;
316  std::call_once(logger_flag, []() { boost::log::core::get()->remove_all_sinks(); });
317 }
318 
319 namespace {
320 
321 // Remove quotes if they match from beginning and end of string.
322 // Does not check for escaped quotes within string.
323 void unquote(std::string& str) {
324  if (1 < str.size() && (str.front() == '\'' || str.front() == '"') &&
325  str.front() == str.back()) {
326  str.erase(str.size() - 1, 1);
327  str.erase(0, 1);
328  }
329 }
330 
331 } // namespace
332 
333 // Used by boost::program_options when parsing enum Channel.
334 std::istream& operator>>(std::istream& in, Channels& channels) {
335  std::string line;
336  std::getline(in, line);
337  unquote(line);
338  std::regex const rex(R"(\w+)");
339  using TokenItr = std::regex_token_iterator<std::string::iterator>;
340  TokenItr const end;
341  for (TokenItr tok(line.begin(), line.end(), rex); tok != end; ++tok) {
342  auto itr = std::find(ChannelNames.cbegin(), ChannelNames.cend(), *tok);
343  if (itr == ChannelNames.cend()) {
344  in.setstate(std::ios_base::failbit);
345  break;
346  } else {
347  channels.emplace(static_cast<Channel>(itr - ChannelNames.cbegin()));
348  }
349  }
350  return in;
351 }
352 
353 // Used by boost::program_options when stringifying Channels.
354 std::ostream& operator<<(std::ostream& out, Channels const& channels) {
355  int i = 0;
356  for (auto const channel : channels) {
357  out << (i++ ? " " : "") << ChannelNames.at(channel);
358  }
359  return out;
360 }
361 
362 // Used by boost::program_options when parsing enum Severity.
363 std::istream& operator>>(std::istream& in, Severity& sev) {
364  std::string token;
365  in >> token;
366  unquote(token);
367  auto itr = std::find(SeverityNames.cbegin(), SeverityNames.cend(), token);
368  if (itr == SeverityNames.cend()) {
369  in.setstate(std::ios_base::failbit);
370  } else {
371  sev = static_cast<Severity>(itr - SeverityNames.cbegin());
372  }
373  return in;
374 }
375 
376 // Used by boost::program_options when stringifying enum Severity.
377 std::ostream& operator<<(std::ostream& out, Severity const& sev) {
378  return out << SeverityNames.at(sev);
379 }
380 
382  : is_channel_(true)
383  , enum_value_(channel)
384  , record_(std::make_unique<boost::log::record>(
385  gChannelLogger::get().open_record(boost::log::keywords::channel = channel))) {
386  if (*record_) {
387  stream_ = std::make_unique<boost::log::record_ostream>(*record_);
388  }
389 }
390 
392  : is_channel_(false)
393  , enum_value_(severity)
394  , record_(std::make_unique<boost::log::record>(gSeverityLogger::get().open_record(
395  boost::log::keywords::severity = severity))) {
396  if (*record_) {
397  stream_ = std::make_unique<boost::log::record_ostream>(*record_);
398  }
399 }
400 
402  if (stream_) {
403  if (is_channel_) {
404  gChannelLogger::get().push_record(boost::move(stream_->get_record()));
405  } else {
406  gSeverityLogger::get().push_record(boost::move(stream_->get_record()));
407  }
408  }
409  if (!is_channel_ && static_cast<Severity>(enum_value_) == Severity::FATAL) {
410  if (FatalFunc fatal_func = g_fatal_func.load()) {
411  // set_once_fatal_func() prevents race condition.
412  // Exceptions thrown by (*fatal_func)() are propagated here.
413  std::call_once(g_fatal_func_flag, *fatal_func);
414  }
415  abort();
416  }
417 }
418 
419 Logger::operator bool() const {
420  return static_cast<bool>(stream_);
421 }
422 
423 boost::log::record_ostream& Logger::stream(char const* file, int line) {
424  return *stream_ << thread_id() << ' ' << filename(file) << ':' << line << ' ';
425 }
426 
427 // DebugTimer-related classes and functions.
428 using Clock = std::chrono::steady_clock;
429 
430 class DurationTree;
431 
432 class Duration {
434  Clock::time_point const start_;
435  Clock::time_point stop_;
436 
437  public:
438  int const depth_;
440  char const* const file_;
441  int const line_;
442  char const* const name_;
443 
444  Duration(DurationTree* duration_tree,
445  int depth,
446  Severity severity,
447  char const* file,
448  int line,
449  char const* name)
450  : duration_tree_(duration_tree)
451  , start_(Clock::now())
452  , depth_(depth)
453  , severity_(severity)
454  , file_(file)
455  , line_(line)
456  , name_(name) {}
457  bool stop();
458  // Start time relative to parent DurationTree::start_.
459  template <typename Units = std::chrono::milliseconds>
460  typename Units::rep relative_start_time() const;
461  // Duration value = stop_ - start_.
462  template <typename Units = std::chrono::milliseconds>
463  typename Units::rep value() const;
464 };
465 
466 using DurationTreeNode = boost::variant<Duration, DurationTree&>;
467 using DurationTreeNodes = std::deque<DurationTreeNode>;
468 
471  int current_depth_; //< Depth of next DurationTreeNode.
472 
473  public:
474  int const depth_; //< Depth of tree within parent tree, 0 for root tree.
475  Clock::time_point const start_;
477  DurationTree(ThreadId thread_id, int start_depth)
478  // Add +1 to current_depth_ for non-root DurationTrees for extra indentation.
479  : current_depth_(start_depth + bool(start_depth))
480  , depth_(start_depth)
481  , start_(Clock::now())
482  , thread_id_(thread_id) {}
483  void pushDurationTree(DurationTree& duration_tree) {
484  durations_.emplace_back(duration_tree);
485  }
486  const Duration& rootDuration() const {
487  CHECK(!durations_.empty());
488  return boost::get<Duration>(durations_.front());
489  }
490  int currentDepth() const { return current_depth_; }
492  DurationTreeNodes const& durations() const { return durations_; }
493  template <typename... Ts>
495  durations_.emplace_back(Duration(this, current_depth_++, std::forward<Ts>(args)...));
496  return boost::get<Duration>(&durations_.back());
497  }
498 };
499 
503  stop_ = Clock::now();
505  return depth_ == 0;
506 }
507 
508 template <typename Units>
509 typename Units::rep Duration::relative_start_time() const {
510  return std::chrono::duration_cast<Units>(start_ - duration_tree_->start_).count();
511 }
512 
513 template <typename Units>
514 typename Units::rep Duration::value() const {
515  return std::chrono::duration_cast<Units>(stop_ - start_).count();
516 }
517 
518 struct GetDepth : boost::static_visitor<int> {
519  int operator()(Duration const& duration) const { return duration.depth_; }
520  int operator()(DurationTree const& duration_tree) const { return duration_tree.depth_; }
521 };
522 
523 using DurationTreeMap = std::unordered_map<ThreadId, std::unique_ptr<DurationTree>>;
524 
527 std::atomic<ThreadId> g_next_thread_id{0};
528 ThreadId thread_local const g_thread_id = g_next_thread_id++;
529 
530 template <typename... Ts>
531 Duration* newDuration(Severity severity, Ts&&... args) {
532  if (g_enable_debug_timer) {
533  std::lock_guard<std::mutex> lock_guard(g_duration_tree_map_mutex);
534  auto& duration_tree_ptr = g_duration_tree_map[g_thread_id];
535  if (!duration_tree_ptr) {
536  duration_tree_ptr = std::make_unique<DurationTree>(g_thread_id, 0);
537  }
538  return duration_tree_ptr->newDuration(severity, std::forward<Ts>(args)...);
539  }
540  return nullptr; // Inactive - don't measure or report timing.
541 }
542 
543 std::ostream& operator<<(std::ostream& os, Duration const& duration) {
544  return os << std::setw(2 * duration.depth_) << ' ' << duration.value() << "ms start("
545  << duration.relative_start_time() << "ms) " << duration.name_ << ' '
546  << filename(duration.file_) << ':' << duration.line_;
547 }
548 
549 std::ostream& operator<<(std::ostream& os, DurationTree const& duration_tree) {
550  os << std::setw(2 * duration_tree.depth_) << ' ' << "New thread("
551  << duration_tree.thread_id_ << ')';
552  for (auto const& duration_tree_node : duration_tree.durations()) {
553  os << '\n' << duration_tree_node;
554  }
555  return os << '\n'
556  << std::setw(2 * duration_tree.depth_) << ' ' << "End thread("
557  << duration_tree.thread_id_ << ')';
558 }
559 
560 // Only called by logAndEraseDurationTree() on root tree
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) {
569  os << '\n' << *itr;
570  }
571  return os;
572 }
573 
574 // Encode DurationTree into json.
575 // DurationTrees encode parent/child relationships using a combination
576 // of ordered descendents, and an int depth member value for each node.
577 // Direct-child nodes are those which:
578 // * do not come after a node of depth <= parent_depth
579 // * have depth == parent_depth + 1
580 class JsonEncoder : boost::static_visitor<rapidjson::Value> {
581  std::shared_ptr<rapidjson::Document> doc_;
582  rapidjson::Document::AllocatorType& alloc_;
583  // Iterators are used to determine children when visiting a Duration node.
584  DurationTreeNodes::const_iterator begin_;
585  DurationTreeNodes::const_iterator end_;
586 
587  JsonEncoder(JsonEncoder& json_encoder,
588  DurationTreeNodes::const_iterator begin,
589  DurationTreeNodes::const_iterator end)
590  : doc_(json_encoder.doc_), alloc_(doc_->GetAllocator()), begin_(begin), end_(end) {}
591 
592  public:
594  : doc_(std::make_shared<rapidjson::Document>(rapidjson::kObjectType))
595  , alloc_(doc_->GetAllocator()) {}
596  rapidjson::Value operator()(Duration const& duration) {
597  rapidjson::Value retval(rapidjson::kObjectType);
598  retval.AddMember("type", "duration", alloc_);
599  retval.AddMember("duration_ms", rapidjson::Value(duration.value()), alloc_);
600  retval.AddMember(
601  "start_ms", rapidjson::Value(duration.relative_start_time()), alloc_);
602  retval.AddMember("name", rapidjson::StringRef(duration.name_), alloc_);
603  retval.AddMember("file", filename(duration.file_), alloc_);
604  retval.AddMember("line", rapidjson::Value(duration.line_), alloc_);
605  retval.AddMember("children", childNodes(duration.depth_), alloc_);
606  return retval;
607  }
608  rapidjson::Value operator()(DurationTree const& duration_tree) {
609  begin_ = duration_tree.durations().cbegin();
610  end_ = duration_tree.durations().cend();
611  rapidjson::Value retval(rapidjson::kObjectType);
612  retval.AddMember("type", "duration_tree", alloc_);
613  retval.AddMember("thread_id", std::to_string(duration_tree.thread_id_), alloc_);
614  retval.AddMember("children", childNodes(duration_tree.depth_), alloc_);
615  return retval;
616  }
617  rapidjson::Value childNodes(int const parent_depth) {
618  GetDepth const get_depth;
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) {
623  break;
624  }
625  if (depth == parent_depth + 1) {
626  JsonEncoder json_encoder(*this, std::next(itr), end_);
627  children.PushBack(apply_visitor(json_encoder, *itr), alloc_);
628  }
629  }
630  return children;
631  }
632  // The root Duration is the "timer" node in the top level debug json object.
633  // Only root Duration has overall total_duration_ms.
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_);
642  retval.AddMember(
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_);
646  }
647  return retval;
648  }
649  // Assumes *doc_ is empty.
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()};
656  }
657 };
658 
660 struct EraseDurationTrees : boost::static_visitor<> {
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);
664  }
665  g_duration_tree_map.erase(itr);
666  }
667  void operator()(Duration const&) const {}
668  void operator()(DurationTree const& duration_tree) const {
669  for (auto const& duration_tree_node : duration_tree.durations()) {
670  apply_visitor(*this, duration_tree_node);
671  }
672  g_duration_tree_map.erase(duration_tree.thread_id_);
673  }
674 };
675 
676 void logAndEraseDurationTree(std::string* json_str) {
677  std::lock_guard<std::mutex> lock_guard(g_duration_tree_map_mutex);
678  DurationTreeMap::const_iterator const itr = g_duration_tree_map.find(g_thread_id);
679  CHECK(itr != g_duration_tree_map.cend());
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;
683  }
684  if (json_str) {
685  JsonEncoder json_encoder;
686  *json_str = json_encoder.str(*itr);
687  }
688  EraseDurationTrees erase_duration_trees;
689  erase_duration_trees(itr);
690 }
691 
692 DebugTimer::DebugTimer(Severity severity, char const* file, int line, char const* name)
693  : duration_(newDuration(severity, file, line, name)) {}
694 
696  stop();
697 }
698 
700  if (duration_) {
701  if (duration_->stop()) {
702  logAndEraseDurationTree(nullptr);
703  }
704  duration_ = nullptr;
705  }
706 }
707 
709  std::string json_str;
710  if (duration_) {
711  if (duration_->stop()) {
712  logAndEraseDurationTree(&json_str);
713  }
714  duration_ = nullptr;
715  }
716  return json_str;
717 }
718 
721 void debug_timer_new_thread(ThreadId parent_thread_id) {
722  std::lock_guard<std::mutex> lock_guard(g_duration_tree_map_mutex);
723  auto parent_itr = g_duration_tree_map.find(parent_thread_id);
724  CHECK(parent_itr != g_duration_tree_map.end());
725  auto const current_depth = parent_itr->second->currentDepth();
726  auto& duration_tree_ptr = g_duration_tree_map[g_thread_id];
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);
730 }
731 
733  return g_thread_id;
734 }
735 
736 } // namespace logger
737 
738 #endif // #ifndef __CUDACC__
std::istream & operator>>(std::istream &in, Channels &channels)
Definition: Logger.cpp:334
DurationTreeNodes::const_iterator end_
Definition: Logger.cpp:585
void pushDurationTree(DurationTree &duration_tree)
Definition: Logger.cpp:483
void debug_timer_new_thread(ThreadId parent_thread_id)
Definition: Logger.cpp:721
std::unique_ptr< boost::program_options::options_description > options_
Definition: Logger.h:110
int const enum_value_
Definition: Logger.h:159
constexpr std::array< char const *, 3 > ChannelNames
Definition: Logger.h:63
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:523
std::string replace_braces(std::string const &str, TAG const tag)
Definition: Logger.cpp:153
std::set< Channel > Channels
Definition: Logger.h:103
std::string stopAndGetJson()
Definition: Logger.cpp:708
std::mutex g_duration_tree_map_mutex
Definition: Logger.cpp:525
boost::log::sources::channel_logger_mt< Channel > ChannelLogger
Definition: Logger.h:150
void set_formatter(SINK &sink)
Definition: Logger.cpp:206
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:587
sinks::text_file_backend::open_handler_type create_or_replace_symlink(boost::weak_ptr< SINK > weak_ptr, std::string &&symlink)
Definition: Logger.cpp:171
std::once_flag g_fatal_func_flag
Definition: Logger.cpp:260
void operator()(DurationTreeMap::const_iterator const &itr) const
Definition: Logger.cpp:661
std::string base_path_
Definition: Logger.h:107
#define const
#define LOG(tag)
Definition: Logger.h:188
Clock::time_point const start_
Definition: Logger.cpp:434
Duration(DurationTree *duration_tree, int depth, Severity severity, char const *file, int line, char const *name)
Definition: Logger.cpp:444
bool g_enable_debug_timer
Definition: Logger.cpp:17
void operator()(Duration const &) const
Definition: Logger.cpp:667
Channel
Definition: Logger.h:61
const std::string json_str(const rapidjson::Value &obj) noexcept
Definition: JsonAccessors.h:44
string name
Definition: setup.in.py:62
DurationTreeNodes durations_
Definition: Logger.cpp:470
void operator()(DurationTree const &duration_tree) const
Definition: Logger.cpp:668
Units::rep relative_start_time() const
Definition: Logger.cpp:509
Clock::time_point const start_
Definition: Logger.cpp:475
Duration * duration_
Definition: Logger.h:296
rapidjson::Value operator()(Duration const &duration)
Definition: Logger.cpp:596
Duration * newDuration(Severity severity, Ts &&...args)
Definition: Logger.cpp:531
Depth-first search and erase all DurationTrees. Not thread-safe.
Definition: Logger.cpp:660
DurationTreeNodes const & durations() const
Definition: Logger.cpp:492
rapidjson::Value childNodes(int const parent_depth)
Definition: Logger.cpp:617
int currentDepth() const
Definition: Logger.cpp:490
void set_once_fatal_func(FatalFunc fatal_func)
Definition: Logger.cpp:307
constexpr std::array< char, 3 > ChannelSymbols
Definition: Logger.h:65
std::string to_string(char const *&&v)
sinks::synchronous_sink< sinks::text_ostream_backend > ClogSync
Definition: Logger.cpp:262
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:442
int const line_
Definition: Logger.cpp:441
constexpr std::array< char, 8 > SeveritySymbols
Definition: Logger.h:94
Units::rep value() const
Definition: Logger.cpp:514
Channels channels_
Definition: Logger.h:120
bool const is_channel_
Definition: Logger.h:158
DurationTreeNodes::const_iterator begin_
Definition: Logger.cpp:584
int const depth_
Definition: Logger.cpp:438
void logAndEraseDurationTree(std::string *json_str)
Definition: Logger.cpp:676
sinks::synchronous_sink< sinks::text_file_backend > FileSync
Definition: Logger.cpp:263
rapidjson::Value operator()(DurationTree const &duration_tree)
Definition: Logger.cpp:608
void init(LogOptions const &log_opts)
Definition: Logger.cpp:280
std::deque< DurationTreeNode > DurationTreeNodes
Definition: Logger.cpp:467
int count
Severity g_min_active_severity
Definition: Logger.cpp:278
std::atomic< FatalFunc > g_fatal_func
Definition: Logger.cpp:259
DebugTimer(Severity, char const *file, int line, char const *name)
Definition: Logger.cpp:692
int operator()(Duration const &duration) const
Definition: Logger.cpp:519
ThreadId thread_local const g_thread_id
Definition: Logger.cpp:528
boost::shared_ptr< FILE_SINK > make_sink(LogOptions const &log_opts, boost::filesystem::path const &full_log_dir, TAG const tag)
Definition: Logger.cpp:225
std::atomic< ThreadId > g_next_thread_id
Definition: Logger.cpp:527
DEVICE auto accumulate(ARGS &&...args)
Definition: gpu_enabled.h:42
bool rotate_daily_
Definition: Logger.h:124
DurationTree *const duration_tree_
Definition: Logger.cpp:433
bool g_enable_smem_group_by true
std::string symlink_
Definition: Logger.h:117
ThreadId const thread_id_
Definition: Logger.cpp:476
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:193
void shutdown()
Definition: Logger.cpp:314
constexpr std::array< char const *, 8 > SeverityNames
Definition: Logger.h:85
rapidjson::Value timer(DurationTreeMap::const_reference kv_pair)
Definition: Logger.cpp:634
uint64_t ThreadId
Definition: Logger.h:306
const Duration & rootDuration() const
Definition: Logger.cpp:486
Severity severity_
Definition: Logger.h:118
std::string str(DurationTreeMap::const_reference kv_pair)
Definition: Logger.cpp:650
bool g_any_active_channels
Definition: Logger.cpp:277
ThreadId thread_id()
Definition: Logger.cpp:732
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:76
#define CHECK(condition)
Definition: Logger.h:197
size_t rotation_size_
Definition: Logger.h:125
int operator()(DurationTree const &duration_tree) const
Definition: Logger.cpp:520
void set_base_path(std::string const &base_path)
Definition: Logger.cpp:93
DurationTreeMap g_duration_tree_map
Definition: Logger.cpp:526
boost::filesystem::path full_log_dir() const
Definition: Logger.cpp:75
char const *const file_
Definition: Logger.cpp:440
int const depth_
Definition: Logger.cpp:474
std::chrono::steady_clock Clock
Definition: Logger.cpp:428
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:164
size_t max_files_
Definition: Logger.h:122
Logger(Channel)
Definition: Logger.cpp:381
void unquote(std::string &str)
Definition: Logger.cpp:323
std::shared_ptr< rapidjson::Document > doc_
Definition: Logger.cpp:581
boost::variant< Duration, DurationTree & > DurationTreeNode
Definition: Logger.cpp:466
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:494
Severity const severity_
Definition: Logger.cpp:439
rapidjson::Document::AllocatorType & alloc_
Definition: Logger.cpp:582
Clock::time_point stop_
Definition: Logger.cpp:435
boost::log::record_ostream & stream(char const *file, int line)
Definition: Logger.cpp:423
void parse_command_line(int, char const *const *)
Definition: Logger.cpp:84