OmniSciDB  72c90bc290
 All Classes Namespaces Files Functions Variables Typedefs Enumerations Enumerator Friends Macros Groups Pages
Logger.h
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 
17 /*
18  * @file Logger.h
19  * @description Use Boost.Log for logging data compatible with previous API.
20  *
21  * Usage:
22  * - Initialize a LogOptions object. E.g.
23  * logger::LogOptions log_options(argv[0]);
24  * - LogOptions can optionally be added to boost::program_options:
25  * help_desc.add(log_options.get_options());
26  * - Initialize global logger once per application:
27  * logger::init(log_options);
28  * - From anywhere in the program:
29  * - LOG(INFO) << "Nice query!";
30  * - LOG(DEBUG4) << "x = " << x;
31  * - CHECK(condition);
32  * - CHECK_LE(x, xmax);
33  * Newlines are automatically appended to log messages.
34  */
35 
36 #ifndef SHARED_LOGGER_H
37 #define SHARED_LOGGER_H
38 
39 #if !(defined(__CUDACC__) || defined(NO_BOOST))
40 
41 #include <boost/config.hpp>
42 #include <boost/log/sources/record_ostream.hpp>
43 
44 #include <memory>
45 #include <set>
46 #include <type_traits>
47 
48 #endif
49 
50 #include <array>
51 #include <sstream>
52 #include <string>
53 #include <thread>
54 
55 #include "../Shared/StackTrace.h"
56 
57 #ifdef ERROR
58 // A common way for this to occur is with a #include <windows.h> which globally defines a
59 // number of macros, such as ERROR, that interferes with other headers. This may be
60 // resolved by locating the new #include that directly or indirectly includes windows.h
61 // (or something else that #defines ERROR) and placing a
62 // #include "Shared/cleanup_global_namespace.h" after it.
63 //
64 // Q: Why not just #include "Shared/cleanup_global_namespace.h" here?
65 //
66 // A: Two reasons:
67 // * ERROR is not the only macro that windows.h defines, e.g. GetObject which
68 // interferes with rapidjson.
69 // * By not cleaning up the global macros at the source requires potential cleaning
70 // on a much larger scale: all places that call LOG(ERROR). (Due to header guards,
71 // #include "Logger.h" may not be included where it needs to in order to clean up.)
72 #error "ERROR must not be globally defined during preprocessing."
73 #endif
74 
75 namespace boost {
76 // Forward declare boost types to avoid including expensive headers.
77 namespace program_options {
78 class options_description;
79 }
80 namespace filesystem {
81 class path;
82 }
83 } // namespace boost
84 
85 extern bool g_enable_debug_timer;
86 
87 namespace logger {
88 
89 // Channel, ChannelNames, and ChannelSymbols must be updated together.
90 // Each Channel has its own ChannelLogger declared below and defined in Logger.cpp.
91 enum Channel { IR = 0, PTX, ASM, EXECUTOR, _NCHANNELS };
92 
93 constexpr std::array<char const*, 4> ChannelNames{"IR", "PTX", "ASM", "EXECUTOR"};
94 
95 constexpr std::array<char, 4> ChannelSymbols{'R', 'P', 'A', 'X'};
96 
97 static_assert(Channel::_NCHANNELS == ChannelNames.size(),
98  "Size of ChannelNames must equal number of Channels.");
99 static_assert(Channel::_NCHANNELS == ChannelSymbols.size(),
100  "Size of ChannelSymbols must equal number of Channels.");
101 
102 // Severity, SeverityNames, and SeveritySymbols must be updated together.
103 enum Severity {
104  DEBUG4 = 0,
112  _NSEVERITIES // number of severity levels
113 };
114 
115 constexpr std::array<char const*, 8> SeverityNames{"DEBUG4",
116  "DEBUG3",
117  "DEBUG2",
118  "DEBUG1",
119  "INFO",
120  "WARNING",
121  "ERROR",
122  "FATAL"};
123 
124 constexpr std::array<char, 8> SeveritySymbols{'4', '3', '2', '1', 'I', 'W', 'E', 'F'};
125 
126 static_assert(Severity::_NSEVERITIES == SeverityNames.size(),
127  "Size of SeverityNames must equal number of Severity levels.");
128 static_assert(Severity::_NSEVERITIES == SeveritySymbols.size(),
129  "Size of SeveritySymbols must equal number of Severity levels.");
130 
131 using RequestId = uint64_t;
132 using ThreadId = uint64_t;
133 
134 class LocalIdsScopeGuard;
135 
139  ThreadLocalIds() = default;
141  : request_id_(request_id), thread_id_(thread_id) {}
142  // Call to assign a new thread_id.
143  // The return value MUST be held otherwise g_thread_local_ids will immediately revert.
145 };
146 
147 static_assert(std::is_standard_layout<ThreadLocalIds>::value);
148 static_assert(std::is_trivial<ThreadLocalIds>::value);
149 
150 // On destruction, reset g_thread_local_ids to original value.
151 // May be needed by thread managers that recycle threads, such as TBB.
152 class [[nodiscard]] LocalIdsScopeGuard {
154 #ifndef NDEBUG
155  // To verify g_thread_local_ids is unchanged during LocalIdsScopeGuard's lifetime.
157 #endif
158  bool enabled_; // Reset g_thread_local_ids iff enabled_.
159 
160  // Used by move constructor + assignment operator.
161  // OK since all member variables are PODs.
162  LocalIdsScopeGuard(LocalIdsScopeGuard const&) = default;
163  LocalIdsScopeGuard& operator=(LocalIdsScopeGuard const&) = default;
164 
165  public:
166 #ifndef NDEBUG
167  LocalIdsScopeGuard(ThreadLocalIds const prev_local_ids,
169  : prev_local_ids_(prev_local_ids)
170  , thread_local_ids_(thread_local_ids)
171  , enabled_(true) {}
172 #else
173  LocalIdsScopeGuard(ThreadLocalIds const prev_local_ids, ThreadLocalIds)
174  : prev_local_ids_(prev_local_ids), enabled_(true) {}
175 #endif
176  // clang-format off
178  // clang-format on
179  rhs.enabled_ = false;
180  }
182  *this = rhs;
183  rhs.enabled_ = false;
184  return *this;
185  }
187 };
188 
191 ThreadLocalIds thread_local_ids();
192 // Assign new request_id and return it.
193 // Assign new thread_id iff current thread_id is 0.
196 
197 #if !(defined(__CUDACC__) || defined(NO_BOOST))
198 
199 using Channels = std::set<Channel>;
200 
201 // Filled by boost::program_options
202 class LogOptions {
203  std::string base_path_{"."}; // ignored if log_dir_ is absolute.
204  // boost::program_options::options_description is not copyable so unique_ptr
205  // allows for modification after initialization (e.g. changing default values.)
206  std::unique_ptr<boost::program_options::options_description> options_;
207 
208  public:
209  // Initialize to default values
210  std::unique_ptr<boost::filesystem::path> log_dir_;
211  // file_name_pattern and symlink are prepended with base_name.
212  std::string file_name_pattern_{".{SEVERITY}.%Y%m%d-%H%M%S.log"};
213  std::string symlink_{".{SEVERITY}"};
217  bool auto_flush_{true};
218  size_t max_files_{100};
219  size_t min_free_space_{20 << 20};
220  bool rotate_daily_{true};
221  size_t rotation_size_{10 << 20};
222 
223  LogOptions(char const* argv0);
224  ~LogOptions(); // Needed to allow forward declarations within std::unique_ptr.
225  boost::filesystem::path full_log_dir() const;
226  boost::program_options::options_description const& get_options() const;
227  void parse_command_line(int, char const* const*);
228  void set_base_path(std::string const& base_path);
229  void set_options();
230 };
231 
232 // Execute once in main() to initialize boost loggers.
233 void init(LogOptions const&);
234 
235 // Flush all sinks.
236 // https://www.boost.org/libs/log/doc/html/log/rationale/why_crash_on_term.html
237 void shutdown();
238 
239 struct LogShutdown {
240  inline ~LogShutdown() { shutdown(); }
241 };
242 
243 // Optional pointer to function to call on LOG(FATAL).
244 using FatalFunc = void (*)() noexcept;
246 
247 // Lifetime of Logger is each call to LOG().
248 class Logger {
249  bool const is_channel_;
250  int const enum_value_;
251  // Pointers are used to minimize size of inline objects.
252  std::unique_ptr<boost::log::record> record_;
253  std::unique_ptr<boost::log::record_ostream> stream_;
254 
255  public:
256  explicit Logger(Channel);
257  explicit Logger(Severity);
258  Logger(Logger&&) = default;
259  ~Logger();
260  operator bool() const;
261  // Must check operator bool() first before calling stream().
262  boost::log::record_ostream& stream(char const* file, int line);
263 };
264 
266  extern bool g_any_active_channels;
267  return g_any_active_channels;
268 }
269 
270 inline bool fast_logging_check(Severity severity) {
272  return g_min_active_severity <= severity;
273 }
274 
275 // These macros risk inadvertent else-matching to the if statements,
276 // which are fortunately prevented by our clang-tidy requirements.
277 // These can be changed to for/while loops with slight performance degradation.
278 
279 #define SLOG(severity_or_channel) \
280  if (auto _heavydb_logger_severity_or_channel_ = severity_or_channel; \
281  logger::fast_logging_check(_heavydb_logger_severity_or_channel_)) \
282  if (auto _heavydb_logger_ = logger::Logger(_heavydb_logger_severity_or_channel_)) \
283  _heavydb_logger_.stream(__FILE__, __LINE__)
284 
285 #define LOG(tag) SLOG(logger::tag)
286 
287 #define LOGGING(tag) logger::fast_logging_check(logger::tag)
288 
289 #define VLOGGING(n) logger::fast_logging_check(logger::DEBUG##n)
290 
291 #define CHECK(condition) \
292  if (BOOST_UNLIKELY(!(condition))) \
293  LOG(FATAL) << "Check failed: " #condition "\n" \
294  << "Stack trace:\n" \
295  << getCurrentStackTrace(1, nullptr, false)
296 
297 #define CHECK_OP(OP, x, y) \
298  if (std::string* fatal_msg = logger::Check##OP(x, y, #x, #y)) \
299  LOG(FATAL) << *std::unique_ptr<std::string>(fatal_msg)
300 
301 #define CHECK_EQ(x, y) CHECK_OP(EQ, x, y)
302 #define CHECK_NE(x, y) CHECK_OP(NE, x, y)
303 #define CHECK_LT(x, y) CHECK_OP(LT, x, y)
304 #define CHECK_LE(x, y) CHECK_OP(LE, x, y)
305 #define CHECK_GT(x, y) CHECK_OP(GT, x, y)
306 #define CHECK_GE(x, y) CHECK_OP(GE, x, y)
307 
308 template <typename X, typename Y>
309 BOOST_NOINLINE std::string* check_failed(X const& x,
310  Y const& y,
311  char const* xstr,
312  char const* ystr,
313  char const* op_str) {
314  std::stringstream ss;
315  ss << "Check failed: " << xstr << op_str << ystr << " (" << x << op_str << y << ")\n";
316  ss << "Stack trace:\n" << getCurrentStackTrace(1, nullptr, false);
317  return new std::string(ss.str()); // Deleted by CHECK_OP macro.
318 }
319 
320 // Complexity comes from requirement that x and y be evaluated only once.
321 #define HEAVYDB_CHECKOP_FUNCTION(name, op) \
322  template <typename X, typename Y> \
323  inline std::string* Check##name( \
324  X const& x, Y const& y, char const* xstr, char const* ystr) { \
325  if (BOOST_LIKELY(x op y)) \
326  return nullptr; \
327  else \
328  return logger::check_failed(x, y, xstr, ystr, " " #op " "); \
329  }
336 #undef HEAVYDB_CHECKOP_FUNCTION
337 
338 #define UNREACHABLE() LOG(FATAL) << "UNREACHABLE "
339 
340 #else // __CUDACC__
341 
342 // Provided for backward compatibility to allow code to compile.
343 // No logging is actually done, since cuda code should not log.
344 template <Severity severity>
345 class NullLogger {
346  public:
347  NullLogger() {
348  if /*constexpr*/ (severity == Severity::FATAL) {
349  abort();
350  }
351  }
352  template <typename T>
353 #ifndef SUPPRESS_NULL_LOGGER_DEPRECATION_WARNINGS
354  [[deprecated]]
355 #endif
356  // If you are here because of a deprecation warning, that is because the code
357  // is attempting to log something in cuda (e.g. CHECK macros). It should
358  // probably be fixed there.
359  NullLogger&
360  operator<<(const T&) {
361  return *this;
362  }
363 };
364 
365 #define LOG(severity) logger::NullLogger<logger::Severity::severity>()
366 
367 #define LOGGING(tag) false
368 
369 #define VLOGGING(n) false
370 
371 #define CHECK(condition) LOG_IF(FATAL, !(condition))
372 
373 #define CHECK_EQ(x, y) CHECK((x) == (y))
374 #define CHECK_NE(x, y) CHECK((x) != (y))
375 #define CHECK_LT(x, y) CHECK((x) < (y))
376 #define CHECK_LE(x, y) CHECK((x) <= (y))
377 #define CHECK_GT(x, y) CHECK((x) > (y))
378 #define CHECK_GE(x, y) CHECK((x) >= (y))
379 
380 #define UNREACHABLE() LOG(FATAL)
381 
382 #endif // __CUDACC__
383 
384 #define LOG_IF(severity, condition) \
385  if (condition) \
386  LOG(severity)
387 
388 #define VLOG(n) LOG(DEBUG##n)
389 
390 class Duration;
391 
392 class DebugTimer {
394  DebugTimer(DebugTimer const&) = delete;
395  DebugTimer(DebugTimer&&) = delete;
396  DebugTimer& operator=(DebugTimer const&) = delete;
397  DebugTimer& operator=(DebugTimer&&) = delete;
398 
399  public:
400  DebugTimer(Severity, char const* file, int line, char const* name);
401  ~DebugTimer();
402  void stop();
403  // json is returned only when called on the root DurationTree.
404  std::string stopAndGetJson();
405 };
406 
407 boost::filesystem::path get_log_dir_path();
408 
409 void debug_timer_new_thread(ThreadId const parent_thread_id);
410 
411 // Typical usage: auto timer = DEBUG_TIMER(__func__);
412 #define DEBUG_TIMER(name) logger::DebugTimer(logger::INFO, __FILE__, __LINE__, name)
413 
414 // This MUST NOT be called more than once per thread, otherwise a failed CHECK() occurs.
415 // Best practice is to call it from the point where the new thread is spawned.
416 // Beware of threads that are re-used.
417 #define DEBUG_TIMER_NEW_THREAD(parent_thread_id) \
418  do { \
419  if (g_enable_debug_timer) \
420  logger::debug_timer_new_thread(parent_thread_id); \
421  } while (false)
422 
423 } // namespace logger
424 
425 #endif // SHARED_LOGGER_H
std::unique_ptr< boost::program_options::options_description > options_
Definition: Logger.h:206
int const enum_value_
Definition: Logger.h:250
size_t min_free_space_
Definition: Logger.h:219
std::set< Channel > Channels
Definition: Logger.h:199
std::string stopAndGetJson()
Definition: Logger.cpp:847
LocalIdsScopeGuard(ThreadLocalIds const prev_local_ids, ThreadLocalIds const thread_local_ids)
Definition: Logger.h:167
ThreadLocalIds thread_local_ids_
Definition: Logger.h:156
std::unique_ptr< boost::log::record > record_
Definition: Logger.h:252
LogOptions(char const *argv0)
std::string base_path_
Definition: Logger.h:203
RequestId request_id_
Definition: Logger.h:137
bool g_enable_debug_timer
Definition: Logger.cpp:17
std::string getCurrentStackTrace(uint32_t num_frames_to_skip, const char *stop_at_this_frame, bool skip_void_and_stl_frames)
Definition: StackTrace.cpp:26
Channel
Definition: Logger.h:91
ThreadLocalIds prev_local_ids_
Definition: Logger.h:153
fs::path get_log_dir_path()
Definition: Logger.cpp:904
#define HEAVYDB_CHECKOP_FUNCTION(name, op)
Definition: Logger.h:321
Duration * duration_
Definition: Logger.h:393
void set_once_fatal_func(FatalFunc fatal_func)
Definition: Logger.cpp:394
ThreadLocalIds(RequestId const request_id, ThreadId const thread_id)
Definition: Logger.h:140
void(*)() noexcept FatalFunc
Definition: Logger.h:244
LocalIdsScopeGuard & operator=(LocalIdsScopeGuard &&rhs)
Definition: Logger.h:181
constexpr std::array< char, 8 > SeveritySymbols
Definition: Logger.h:124
Channels channels_
Definition: Logger.h:216
bool const is_channel_
Definition: Logger.h:249
bool fast_logging_check(Channel)
Definition: Logger.h:265
void init(LogOptions const &log_opts)
Definition: Logger.cpp:364
Severity g_min_active_severity
Definition: Logger.cpp:360
void debug_timer_new_thread(ThreadId const parent_thread_id)
Definition: Logger.cpp:861
RequestId set_new_request_id()
Definition: Logger.cpp:889
constexpr std::array< char const *, 4 > ChannelNames
Definition: Logger.h:93
bool rotate_daily_
Definition: Logger.h:220
void set_request_id(RequestId const request_id)
Definition: Logger.cpp:897
BOOST_NOINLINE std::string * check_failed(X const &x, Y const &y, char const *xstr, char const *ystr, char const *op_str)
Definition: Logger.h:309
bool g_enable_smem_group_by true
std::string symlink_
Definition: Logger.h:213
DebugTimer & operator=(DebugTimer const &)=delete
DebugTimer(DebugTimer const &)=delete
std::unique_ptr< boost::log::record_ostream > stream_
Definition: Logger.h:253
tuple line
Definition: parse_ast.py:10
LocalIdsScopeGuard setNewThreadId() const
Definition: Logger.cpp:538
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:276
void shutdown()
Definition: Logger.cpp:401
constexpr std::array< char const *, 8 > SeverityNames
Definition: Logger.h:115
constexpr std::array< char, 4 > ChannelSymbols
Definition: Logger.h:95
uint64_t ThreadId
Definition: Logger.h:132
std::unique_ptr< boost::filesystem::path > log_dir_
Definition: Logger.h:210
Severity severity_
Definition: Logger.h:214
bool g_any_active_channels
Definition: Logger.cpp:359
ThreadId thread_id()
Definition: Logger.cpp:877
RequestId request_id()
Definition: Logger.cpp:874
boost::program_options::options_description const & get_options() const
std::string file_name_pattern_
Definition: Logger.h:212
size_t rotation_size_
Definition: Logger.h:221
void set_base_path(std::string const &base_path)
boost::filesystem::path full_log_dir() const
size_t max_files_
Definition: Logger.h:218
Logger(Channel)
Definition: Logger.cpp:492
ThreadId thread_id_
Definition: Logger.h:138
string name
Definition: setup.in.py:72
LocalIdsScopeGuard(LocalIdsScopeGuard &&rhs)
Definition: Logger.h:177
Severity severity_clog_
Definition: Logger.h:215
ThreadLocalIds thread_local_ids()
Definition: Logger.cpp:880
uint64_t RequestId
Definition: Logger.h:131
boost::log::record_ostream & stream(char const *file, int line)
Definition: Logger.cpp:554
void parse_command_line(int, char const *const *)