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