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