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