23 #include <rapidjson/document.h>
24 #include <rapidjson/stringbuffer.h>
25 #include <rapidjson/writer.h>
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>
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;
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)
74 (keywords::channel =
IR))
77 (keywords::channel =
PTX))
80 (keywords::channel =
ASM))
84 std::
string filename(
char const* path) {
85 return boost::filesystem::path(path).filename().string();
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_;
99 LogOptions::~LogOptions() {}
101 boost::filesystem::path LogOptions::full_log_dir()
const {
102 return log_dir_->has_root_directory() ? *log_dir_ : base_path_ / *log_dir_;
105 po::options_description
const& LogOptions::get_options()
const {
110 void LogOptions::parse_command_line(
int argc,
char const*
const* argv) {
111 po::variables_map vm;
113 po::command_line_parser(argc, argv).options(*options_).allow_unregistered().run(),
119 void LogOptions::set_base_path(std::string
const& base_path) {
120 base_path_ = base_path;
124 void LogOptions::set_options() {
125 options_ = std::make_unique<boost::program_options::options_description>(
"Logging");
126 std::string
const channels =
130 [](
auto a,
auto channel) {
return a +
' ' + channel; });
132 std::string severities;
134 if (!boost::algorithm::starts_with(
name,
"DEBUG")) {
135 (severities += (severities.empty() ?
"" :
" ")) +=
name;
138 options_->add_options()(
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()(
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()(
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()(
174 po::value<size_t>(&rotation_size_)->default_value(rotation_size_),
175 "Maximum file size in bytes before new log files are started.");
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 (std::is_same<TAG, Channel>::value) {
183 return std::regex_replace(str, regex,
ChannelNames[tag]);
185 return std::regex_replace(str, regex, SeverityNames[tag]);
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;
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;
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);
209 stream <<
filename(__FILE__) <<
':' << __LINE__ <<
' ' << ec.message() <<
'\n';
211 fs::create_symlink(file_name.filename(), symlink_path, ec);
213 stream <<
filename(__FILE__) <<
':' << __LINE__ <<
' ' << ec.message() <<
'\n';
220 boost::log::formatting_ostream& strm,
221 boost::log::to_log_manip<Channel, tag::channel>
const& manip) {
226 boost::log::formatting_ostream& strm,
227 boost::log::to_log_manip<Severity, tag::severity>
const& manip) {
231 template <
typename TAG,
typename SINK>
232 void set_formatter(SINK& sink) {
233 if (std::is_same<TAG, Channel>::value) {
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);
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);
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,
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 (std::is_same<TAG, Channel>::value) {
260 sink->set_filter(channel == static_cast<Channel>(tag));
261 set_formatter<Channel>(sink);
266 : static_cast<Severity>(tag);
267 sink->set_filter(min_filter_level <= severity);
268 set_formatter<Severity>(sink);
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));
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();
285 std::atomic<FatalFunc> g_fatal_func{
nullptr};
288 using ClogSync = sinks::synchronous_sink<sinks::text_ostream_backend>;
289 using FileSync = sinks::synchronous_sink<sinks::text_file_backend>;
291 template <
typename CONSOLE_SINK>
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);
297 set_formatter<Severity>(sink);
309 boost::shared_ptr<boost::log::core> core = boost::log::core::get();
311 core->add_global_attribute(
"TimeStamp", attr::local_clock());
312 core->add_global_attribute(
"ProcessID", attr::current_process_id());
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);
320 core->add_sink(make_sink<FileSync>(log_opts, full_log_dir, level));
323 if (log_dir_was_created) {
324 LOG(
INFO) <<
"Log directory(" << full_log_dir.native() <<
") created.";
326 for (
auto const channel : log_opts.
channels_) {
327 core->add_sink(make_sink<FileSync>(log_opts, full_log_dir, channel));
331 core->add_sink(make_sink<ClogSync>(log_opts));
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.");
345 static std::once_flag logger_flag;
346 std::call_once(logger_flag, []() {
347 boost::log::core::get()->remove_all_sinks();
357 if (1 < str.size() && (str.front() ==
'\'' || str.front() ==
'"') &&
358 str.front() == str.back()) {
359 str.erase(str.size() - 1, 1);
369 std::getline(in, line);
371 std::regex
const rex(R
"(\w+)");
372 using TokenItr = std::regex_token_iterator<std::string::iterator>;
374 for (TokenItr tok(line.begin(), line.end(), rex); tok != end; ++tok) {
377 in.setstate(std::ios_base::failbit);
380 channels.emplace(static_cast<Channel>(itr -
ChannelNames.cbegin()));
389 for (
auto const channel : channels) {
400 auto itr = std::find(SeverityNames.cbegin(), SeverityNames.cend(), token);
401 if (itr == SeverityNames.cend()) {
402 in.setstate(std::ios_base::failbit);
404 sev =
static_cast<Severity>(itr - SeverityNames.cbegin());
411 return out << SeverityNames.at(sev);
419 return gChannelLogger_IR::get();
421 return gChannelLogger_PTX::get();
423 return gChannelLogger_ASM::get();
430 , enum_value_(channel)
431 , record_(std::make_unique<boost::log::record>(
434 stream_ = std::make_unique<boost::log::record_ostream>(*record_);
440 , enum_value_(severity)
441 , record_(std::make_unique<boost::log::record>(
442 gSeverityLogger::get().open_record(keywords::severity = severity))) {
444 stream_ = std::make_unique<boost::log::record_ostream>(*record_);
452 .push_record(boost::move(
stream_->get_record()));
454 gSeverityLogger::get().push_record(boost::move(
stream_->get_record()));
458 if (
FatalFunc fatal_func = g_fatal_func.load()) {
467 Logger::operator bool()
const {
468 return static_cast<bool>(stream_);
499 using Clock = std::chrono::steady_clock;
530 template <
typename Units = std::chrono::milliseconds>
533 template <
typename Units = std::chrono::milliseconds>
534 typename Units::rep
value()
const;
559 return boost::get<Duration>(
durations_.front());
564 template <
typename... Ts>
567 return boost::get<Duration>(&
durations_.back());
574 stop_ = Clock::now();
579 template <
typename Units>
584 template <
typename Units>
586 return std::chrono::duration_cast<Units>(
stop_ -
start_).count();
601 template <
typename... Ts>
606 if (!duration_tree_ptr) {
607 duration_tree_ptr = std::make_unique<DurationTree>(
g_thread_id, 0);
609 return duration_tree_ptr->newDuration(severity, std::forward<Ts>(
args)...);
615 return os << std::setw(2 * duration.
depth_) <<
' ' << duration.
value() <<
"ms start("
621 os << std::setw(2 * duration_tree.
depth_) <<
' ' <<
"New thread("
623 for (
auto const& duration_tree_node : duration_tree.
durations()) {
624 os <<
'\n' << duration_tree_node;
627 << std::setw(2 * duration_tree.
depth_) <<
' ' <<
"End thread("
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) {
652 std::shared_ptr<rapidjson::Document>
doc_;
653 rapidjson::Document::AllocatorType&
alloc_;
655 DurationTreeNodes::const_iterator
begin_;
656 DurationTreeNodes::const_iterator
end_;
659 DurationTreeNodes::const_iterator begin,
660 DurationTreeNodes::const_iterator end)
665 :
doc_(std::make_shared<rapidjson::Document>(rapidjson::kObjectType))
668 rapidjson::Value retval(rapidjson::kObjectType);
669 retval.AddMember(
"type",
"duration",
alloc_);
670 retval.AddMember(
"duration_ms", rapidjson::Value(duration.
value()),
alloc_);
673 retval.AddMember(
"name", rapidjson::StringRef(duration.
name_),
alloc_);
675 retval.AddMember(
"line", rapidjson::Value(duration.
line_),
alloc_);
682 rapidjson::Value retval(rapidjson::kObjectType);
683 retval.AddMember(
"type",
"duration_tree",
alloc_);
690 rapidjson::Value children(rapidjson::kArrayType);
692 int const depth = apply_visitor(get_depth, *itr);
693 if (depth <= parent_depth) {
696 if (depth == parent_depth + 1) {
698 children.PushBack(apply_visitor(json_encoder, *itr),
alloc_);
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);
710 auto const& root_duration = boost::get<Duration>(*(
begin_++));
711 retval.AddMember(
"type",
"root",
alloc_);
714 "total_duration_ms", rapidjson::Value(root_duration.value()),
alloc_);
715 retval.AddMember(
"name", rapidjson::StringRef(root_duration.name_),
alloc_);
721 std::string
str(DurationTreeMap::const_reference kv_pair) {
723 rapidjson::StringBuffer buffer;
724 rapidjson::Writer<rapidjson::StringBuffer> writer(buffer);
725 doc_->Accept(writer);
726 return {buffer.GetString(), buffer.GetSize()};
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);
740 for (
auto const& duration_tree_node : duration_tree.
durations()) {
741 apply_visitor(*
this, duration_tree_node);
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;
757 *json_str = json_encoder.
str(*itr);
760 erase_duration_trees(itr);
764 : duration_(
newDuration(severity, file, line, name)) {
799 auto const current_depth = parent_itr->second->currentDepth();
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);
816 parent_itr->second->pushDurationTree(*insert.first->second);
829 #endif // #ifndef __CUDACC__
QidScopeGuard set_thread_local_query_id(QueryId const query_id)
std::istream & operator>>(std::istream &in, Channels &channels)
DurationTreeNodes::const_iterator end_
std::lock_guard< T > lock_guard
void pushDurationTree(DurationTree &duration_tree)
void debug_timer_new_thread(ThreadId parent_thread_id)
constexpr std::array< char const *, 3 > ChannelNames
std::unordered_map< ThreadId, std::unique_ptr< DurationTree >> DurationTreeMap
std::set< Channel > Channels
std::string stopAndGetJson()
std::mutex g_duration_tree_map_mutex
std::unique_ptr< boost::log::record > record_
LogOptions(char const *argv0)
JsonEncoder(JsonEncoder &json_encoder, DurationTreeNodes::const_iterator begin, DurationTreeNodes::const_iterator end)
std::once_flag g_fatal_func_flag
void operator()(DurationTreeMap::const_iterator const &itr) const
std::ostream & operator<<(std::ostream &os, const SessionInfo &session_info)
Clock::time_point const start_
Duration(DurationTree *duration_tree, int depth, Severity severity, char const *file, int line, char const *name)
bool g_enable_debug_timer
void operator()(Duration const &) const
const std::string kDefaultLogDirName
const std::string json_str(const rapidjson::Value &obj) noexcept
DurationTreeNodes durations_
void operator()(DurationTree const &duration_tree) const
boost::filesystem::path get_log_dir_path()
Units::rep relative_start_time() const
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_
rapidjson::Value operator()(Duration const &duration)
Duration * newDuration(Severity severity, Ts &&...args)
Depth-first search and erase all DurationTrees. Not thread-safe.
DurationTreeNodes const & durations() const
rapidjson::Value childNodes(int const parent_depth)
void set_once_fatal_func(FatalFunc fatal_func)
constexpr std::array< char, 3 > ChannelSymbols
boost::log::sources::channel_logger_mt< Channel > ChannelLogger
sinks::synchronous_sink< sinks::text_ostream_backend > ClogSync
void(*)() noexcept FatalFunc
constexpr std::array< char, 8 > SeveritySymbols
void omnisci_range_push(Category c, const char *name, const char *file)
DurationTreeNodes::const_iterator begin_
void logAndEraseDurationTree(std::string *json_str)
sinks::synchronous_sink< sinks::text_file_backend > FileSync
rapidjson::Value operator()(DurationTree const &duration_tree)
void init(LogOptions const &log_opts)
std::deque< DurationTreeNode > DurationTreeNodes
boost::shared_ptr< CONSOLE_SINK > make_sink(LogOptions const &log_opts)
Severity g_min_active_severity
int operator()(Duration const &duration) const
ChannelLogger & get_channel_logger(Channel const channel)
std::atomic< ThreadId > g_next_thread_id
DEVICE auto accumulate(ARGS &&...args)
DurationTree *const duration_tree_
boost::log::sources::severity_logger_mt< Severity > SeverityLogger
bool g_enable_smem_group_by true
ThreadId const thread_id_
DebugTimer(DebugTimer const &)=delete
std::unique_ptr< boost::log::record_ostream > stream_
thread_local std::atomic< QueryId > g_query_id
constexpr std::array< char const *, 8 > SeverityNames
thread_local ThreadId g_thread_id
rapidjson::Value timer(DurationTreeMap::const_reference kv_pair)
const Duration & rootDuration() const
std::string str(DurationTreeMap::const_reference kv_pair)
bool g_any_active_channels
std::string filename(char const *path)
bool g_enable_watchdog false
int operator()(DurationTree const &duration_tree) const
DurationTreeMap g_duration_tree_map
boost::filesystem::path full_log_dir() const
static boost::filesystem::path g_log_dir_path
std::chrono::steady_clock Clock
void unquote(std::string &str)
std::shared_ptr< rapidjson::Document > doc_
boost::variant< Duration, DurationTree & > DurationTreeNode
std::ostream & operator<<(std::ostream &out, Channels const &channels)
Duration * newDuration(Ts &&...args)
rapidjson::Document::AllocatorType & alloc_
boost::log::record_ostream & stream(char const *file, int line)