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