OmniSciDB  ca0c39ec8f
 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 
47 #endif
48 
49 #include <array>
50 #include <sstream>
51 #include <string>
52 #include <thread>
53 
54 #ifdef ERROR
55 // A common way for this to occur is with a #include <windows.h> which globally defines a
56 // number of macros, such as ERROR, that interferes with other headers. This may be
57 // resolved by locating the new #include that directly or indirectly includes windows.h
58 // (or something else that #defines ERROR) and placing a
59 // #include "Shared/cleanup_global_namespace.h" after it.
60 //
61 // Q: Why not just #include "Shared/cleanup_global_namespace.h" here?
62 //
63 // A: Two reasons:
64 // * ERROR is not the only macro that windows.h defines, e.g. GetObject which
65 // interferes with rapidjson.
66 // * By not cleaning up the global macros at the source requires potential cleaning
67 // on a much larger scale: all places that call LOG(ERROR). (Due to header guards,
68 // #include "Logger.h" may not be included where it needs to in order to clean up.)
69 #error "ERROR must not be globally defined during preprocessing."
70 #endif
71 
72 namespace boost {
73 // Forward declare boost types to avoid including expensive headers.
74 namespace program_options {
75 class options_description;
76 }
77 namespace filesystem {
78 class path;
79 }
80 } // namespace boost
81 
82 extern bool g_enable_debug_timer;
83 
84 namespace logger {
85 
86 // Channel, ChannelNames, and ChannelSymbols must be updated together.
87 // Each Channel has its own ChannelLogger declared below and defined in Logger.cpp.
88 enum Channel { IR = 0, PTX, ASM, _NCHANNELS };
89 
90 constexpr std::array<char const*, 3> ChannelNames{"IR", "PTX", "ASM"};
91 
92 constexpr std::array<char, 3> ChannelSymbols{'R', 'P', 'A'};
93 
94 static_assert(Channel::_NCHANNELS == ChannelNames.size(),
95  "Size of ChannelNames must equal number of Channels.");
96 static_assert(Channel::_NCHANNELS == ChannelSymbols.size(),
97  "Size of ChannelSymbols must equal number of Channels.");
98 
99 // Severity, SeverityNames, and SeveritySymbols must be updated together.
100 enum Severity {
101  DEBUG4 = 0,
109  _NSEVERITIES // number of severity levels
110 };
111 
112 constexpr std::array<char const*, 8> SeverityNames{"DEBUG4",
113  "DEBUG3",
114  "DEBUG2",
115  "DEBUG1",
116  "INFO",
117  "WARNING",
118  "ERROR",
119  "FATAL"};
120 
121 constexpr std::array<char, 8> SeveritySymbols{'4', '3', '2', '1', 'I', 'W', 'E', 'F'};
122 
123 static_assert(Severity::_NSEVERITIES == SeverityNames.size(),
124  "Size of SeverityNames must equal number of Severity levels.");
125 static_assert(Severity::_NSEVERITIES == SeveritySymbols.size(),
126  "Size of SeveritySymbols must equal number of Severity levels.");
127 
128 #if !(defined(__CUDACC__) || defined(NO_BOOST))
129 
130 using Channels = std::set<Channel>;
131 
132 // Filled by boost::program_options
133 class LogOptions {
134  std::string base_path_{"."}; // ignored if log_dir_ is absolute.
135  // boost::program_options::options_description is not copyable so unique_ptr
136  // allows for modification after initialization (e.g. changing default values.)
137  std::unique_ptr<boost::program_options::options_description> options_;
138 
139  public:
140  // Initialize to default values
141  std::unique_ptr<boost::filesystem::path> log_dir_;
142  // file_name_pattern and symlink are prepended with base_name.
143  std::string file_name_pattern_{".{SEVERITY}.%Y%m%d-%H%M%S.log"};
144  std::string symlink_{".{SEVERITY}"};
148  bool auto_flush_{true};
149  size_t max_files_{100};
150  size_t min_free_space_{20 << 20};
151  bool rotate_daily_{true};
152  size_t rotation_size_{10 << 20};
153 
154  LogOptions(char const* argv0);
155  ~LogOptions(); // Needed to allow forward declarations within std::unique_ptr.
156  boost::filesystem::path full_log_dir() const;
157  boost::program_options::options_description const& get_options() const;
158  void parse_command_line(int, char const* const*);
159  void set_base_path(std::string const& base_path);
160  void set_options();
161 };
162 
163 // Execute once in main() to initialize boost loggers.
164 void init(LogOptions const&);
165 
166 // Flush all sinks.
167 // https://www.boost.org/libs/log/doc/html/log/rationale/why_crash_on_term.html
168 void shutdown();
169 
170 struct LogShutdown {
171  inline ~LogShutdown() { shutdown(); }
172 };
173 
174 // Optional pointer to function to call on LOG(FATAL).
175 using FatalFunc = void (*)() noexcept;
177 
178 // Lifetime of Logger is each call to LOG().
179 class Logger {
180  bool const is_channel_;
181  int const enum_value_;
182  // Pointers are used to minimize size of inline objects.
183  std::unique_ptr<boost::log::record> record_;
184  std::unique_ptr<boost::log::record_ostream> stream_;
185 
186  public:
187  explicit Logger(Channel);
188  explicit Logger(Severity);
189  Logger(Logger&&) = default;
190  ~Logger();
191  operator bool() const;
192  // Must check operator bool() first before calling stream().
193  boost::log::record_ostream& stream(char const* file, int line);
194 };
195 
197  extern bool g_any_active_channels;
198  return g_any_active_channels;
199 }
200 
201 inline bool fast_logging_check(Severity severity) {
203  return g_min_active_severity <= severity;
204 }
205 
206 // These macros risk inadvertent else-matching to the if statements,
207 // which are fortunately prevented by our clang-tidy requirements.
208 // These can be changed to for/while loops with slight performance degradation.
209 
210 #define SLOG(severity_or_channel) \
211  if (auto _heavydb_logger_severity_or_channel_ = severity_or_channel; \
212  logger::fast_logging_check(_heavydb_logger_severity_or_channel_)) \
213  if (auto _heavydb_logger_ = logger::Logger(_heavydb_logger_severity_or_channel_)) \
214  _heavydb_logger_.stream(__FILE__, __LINE__)
215 
216 #define LOG(tag) SLOG(logger::tag)
217 
218 #define LOGGING(tag) logger::fast_logging_check(logger::tag)
219 
220 #define VLOGGING(n) logger::fast_logging_check(logger::DEBUG##n)
221 
222 #define CHECK(condition) \
223  if (BOOST_UNLIKELY(!(condition))) \
224  LOG(FATAL) << "Check failed: " #condition " "
225 
226 #define CHECK_OP(OP, x, y) \
227  if (std::string* fatal_msg = logger::Check##OP(x, y, #x, #y)) \
228  LOG(FATAL) << *std::unique_ptr<std::string>(fatal_msg)
229 
230 #define CHECK_EQ(x, y) CHECK_OP(EQ, x, y)
231 #define CHECK_NE(x, y) CHECK_OP(NE, x, y)
232 #define CHECK_LT(x, y) CHECK_OP(LT, x, y)
233 #define CHECK_LE(x, y) CHECK_OP(LE, x, y)
234 #define CHECK_GT(x, y) CHECK_OP(GT, x, y)
235 #define CHECK_GE(x, y) CHECK_OP(GE, x, y)
236 
237 template <typename X, typename Y>
238 BOOST_NOINLINE std::string* check_failed(X const& x,
239  Y const& y,
240  char const* xstr,
241  char const* ystr,
242  char const* op_str) {
243  std::stringstream ss;
244  ss << "Check failed: " << xstr << op_str << ystr << " (" << x << op_str << y << ") ";
245  return new std::string(ss.str()); // Deleted by CHECK_OP macro.
246 }
247 
248 // Complexity comes from requirement that x and y be evaluated only once.
249 #define HEAVYDB_CHECKOP_FUNCTION(name, op) \
250  template <typename X, typename Y> \
251  inline std::string* Check##name( \
252  X const& x, Y const& y, char const* xstr, char const* ystr) { \
253  if (BOOST_LIKELY(x op y)) \
254  return nullptr; \
255  else \
256  return logger::check_failed(x, y, xstr, ystr, " " #op " "); \
257  }
264 #undef HEAVYDB_CHECKOP_FUNCTION
265 
266 #define UNREACHABLE() LOG(FATAL) << "UNREACHABLE "
267 
268 #else // __CUDACC__
269 
270 // Provided for backward compatibility to allow code to compile.
271 // No logging is actually done, since cuda code should not log.
272 template <Severity severity>
273 class NullLogger {
274  public:
275  NullLogger() {
276  if /*constexpr*/ (severity == Severity::FATAL) {
277  abort();
278  }
279  }
280  template <typename T>
281 #ifndef SUPPRESS_NULL_LOGGER_DEPRECATION_WARNINGS
282  [[deprecated]]
283 #endif
284  // If you are here because of a deprecation warning, that is because the code
285  // is attempting to log something in cuda (e.g. CHECK macros). It should
286  // probably be fixed there.
287  NullLogger&
288  operator<<(const T&) {
289  return *this;
290  }
291 };
292 
293 #define LOG(severity) logger::NullLogger<logger::Severity::severity>()
294 
295 #define LOGGING(tag) false
296 
297 #define VLOGGING(n) false
298 
299 #define CHECK(condition) LOG_IF(FATAL, !(condition))
300 
301 #define CHECK_EQ(x, y) CHECK((x) == (y))
302 #define CHECK_NE(x, y) CHECK((x) != (y))
303 #define CHECK_LT(x, y) CHECK((x) < (y))
304 #define CHECK_LE(x, y) CHECK((x) <= (y))
305 #define CHECK_GT(x, y) CHECK((x) > (y))
306 #define CHECK_GE(x, y) CHECK((x) >= (y))
307 
308 #define UNREACHABLE() LOG(FATAL)
309 
310 #endif // __CUDACC__
311 
312 #define LOG_IF(severity, condition) \
313  if (condition) \
314  LOG(severity)
315 
316 #define VLOG(n) LOG(DEBUG##n)
317 
318 class Duration;
319 
320 class DebugTimer {
322  DebugTimer(DebugTimer const&) = delete;
323  DebugTimer(DebugTimer&&) = delete;
324  DebugTimer& operator=(DebugTimer const&) = delete;
325  DebugTimer& operator=(DebugTimer&&) = delete;
326 
327  public:
328  DebugTimer(Severity, char const* file, int line, char const* name);
329  ~DebugTimer();
330  void stop();
331  // json is returned only when called on the root DurationTree.
332  std::string stopAndGetJson();
333 };
334 
335 using QueryId = uint64_t;
336 QueryId query_id();
337 
338 // ~QidScopeGuard resets the thread_local g_query_id to 0 if the current value = id_.
339 // In other words, only the QidScopeGuard instance which resulted from changing
340 // g_query_id from zero to non-zero is responsible for resetting it back to zero when it
341 // goes out of scope. All other instances have no effect.
344 
345  public:
346  QidScopeGuard(QueryId const id) : id_{id} {}
347  QidScopeGuard(QidScopeGuard const&) = delete;
348  QidScopeGuard& operator=(QidScopeGuard const&) = delete;
349  QidScopeGuard(QidScopeGuard&& that) : id_(that.id_) { that.id_ = 0; }
351  id_ = that.id_;
352  that.id_ = 0;
353  return *this;
354  }
355  ~QidScopeGuard();
356  QueryId id() const { return id_; }
357 };
358 
359 boost::filesystem::path get_log_dir_path();
360 
361 // Set logger::g_query_id based on given parameter.
362 QidScopeGuard set_thread_local_query_id(QueryId const);
363 
364 using ThreadId = uint64_t;
365 
366 void debug_timer_new_thread(ThreadId parent_thread_id);
367 
369 
370 // Typical usage: auto timer = DEBUG_TIMER(__func__);
371 #define DEBUG_TIMER(name) logger::DebugTimer(logger::INFO, __FILE__, __LINE__, name)
372 
373 // This MUST NOT be called more than once per thread, otherwise a failed CHECK() occurs.
374 // Best practice is to call it from the point where the new thread is spawned.
375 // Beware of threads that are re-used.
376 #define DEBUG_TIMER_NEW_THREAD(parent_thread_id) \
377  do { \
378  if (g_enable_debug_timer) \
379  logger::debug_timer_new_thread(parent_thread_id); \
380  } while (false)
381 
382 } // namespace logger
383 
384 #endif // SHARED_LOGGER_H
QidScopeGuard set_thread_local_query_id(QueryId const query_id)
Definition: Logger.cpp:487
void debug_timer_new_thread(ThreadId parent_thread_id)
Definition: Logger.cpp:795
std::unique_ptr< boost::program_options::options_description > options_
Definition: Logger.h:137
int const enum_value_
Definition: Logger.h:181
constexpr std::array< char const *, 3 > ChannelNames
Definition: Logger.h:90
size_t min_free_space_
Definition: Logger.h:150
std::set< Channel > Channels
Definition: Logger.h:130
std::string stopAndGetJson()
Definition: Logger.cpp:782
QidScopeGuard(QueryId const id)
Definition: Logger.h:346
std::unique_ptr< boost::log::record > record_
Definition: Logger.h:183
LogOptions(char const *argv0)
std::string base_path_
Definition: Logger.h:134
QidScopeGuard(QidScopeGuard &&that)
Definition: Logger.h:349
bool g_enable_debug_timer
Definition: Logger.cpp:17
Channel
Definition: Logger.h:88
boost::filesystem::path get_log_dir_path()
Definition: Logger.cpp:824
#define HEAVYDB_CHECKOP_FUNCTION(name, op)
Definition: Logger.h:249
Duration * duration_
Definition: Logger.h:321
QueryId id() const
Definition: Logger.h:356
void set_once_fatal_func(FatalFunc fatal_func)
Definition: Logger.cpp:337
constexpr std::array< char, 3 > ChannelSymbols
Definition: Logger.h:92
QidScopeGuard & operator=(QidScopeGuard const &)=delete
void(*)() noexcept FatalFunc
Definition: Logger.h:175
constexpr std::array< char, 8 > SeveritySymbols
Definition: Logger.h:121
Channels channels_
Definition: Logger.h:147
bool const is_channel_
Definition: Logger.h:180
uint64_t QueryId
Definition: Logger.h:335
bool fast_logging_check(Channel)
Definition: Logger.h:196
void init(LogOptions const &log_opts)
Definition: Logger.cpp:308
Severity g_min_active_severity
Definition: Logger.cpp:304
bool rotate_daily_
Definition: Logger.h:151
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:238
std::string symlink_
Definition: Logger.h:144
DebugTimer & operator=(DebugTimer const &)=delete
DebugTimer(DebugTimer const &)=delete
std::unique_ptr< boost::log::record_ostream > stream_
Definition: Logger.h:184
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
uint64_t ThreadId
Definition: Logger.h:364
std::unique_ptr< boost::filesystem::path > log_dir_
Definition: Logger.h:141
Severity severity_
Definition: Logger.h:145
bool g_any_active_channels
Definition: Logger.cpp:303
ThreadId thread_id()
Definition: Logger.cpp:820
boost::program_options::options_description const & get_options() const
std::string file_name_pattern_
Definition: Logger.h:143
QueryId query_id()
Definition: Logger.cpp:473
size_t rotation_size_
Definition: Logger.h:152
void set_base_path(std::string const &base_path)
boost::filesystem::path full_log_dir() const
size_t max_files_
Definition: Logger.h:149
Logger(Channel)
Definition: Logger.cpp:428
string name
Definition: setup.in.py:72
std::ostream & operator<<(std::ostream &out, Channels const &channels)
Definition: Logger.cpp:387
QidScopeGuard & operator=(QidScopeGuard &&that)
Definition: Logger.h:350
Severity severity_clog_
Definition: Logger.h:146
boost::log::record_ostream & stream(char const *file, int line)
Definition: Logger.cpp:493
void parse_command_line(int, char const *const *)