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