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 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;
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)
75 (keywords::channel =
IR))
78 (keywords::channel =
PTX))
81 (keywords::channel =
ASM))
85 std::
string filename(
char const* path) {
86 return fs::path(path).filename().string();
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_;
100 LogOptions::~LogOptions() {}
102 fs::path LogOptions::full_log_dir()
const {
103 return log_dir_->has_root_directory() ? *log_dir_ : base_path_ / *log_dir_;
106 po::options_description
const& LogOptions::get_options()
const {
111 void LogOptions::parse_command_line(
int argc,
char const*
const* argv) {
112 po::variables_map vm;
114 po::command_line_parser(argc, argv).options(*options_).allow_unregistered().run(),
120 void LogOptions::set_base_path(std::string
const& base_path) {
121 base_path_ = base_path;
125 void LogOptions::set_options() {
126 options_ = std::make_unique<boost::program_options::options_description>(
"Logging");
127 std::string
const channels =
131 [](
auto a,
auto channel) {
return a +
' ' + channel; });
133 std::string severities;
135 if (!boost::algorithm::starts_with(
name,
"DEBUG")) {
136 (severities += (severities.empty() ?
"" :
" ")) +=
name;
139 options_->add_options()(
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()(
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()(
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()(
175 po::value<size_t>(&rotation_size_)->default_value(rotation_size_),
176 "Maximum file size in bytes before new log files are started.");
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]);
186 return std::regex_replace(str, regex, SeverityNames[tag]);
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;
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) {
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 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);
227 fs::remove(symlink_path, ec);
229 std::cerr <<
"Error removing " << symlink_path <<
": " << ec.message()
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_)) {}
249 collector_->store_file(path);
250 std::for_each(symlink_paths_.begin(), symlink_paths_.end(), RemoveDeadLink{});
252 #if 107900 <= BOOST_VERSION
253 bool is_in_storage(fs::path
const& path)
const override {
254 return collector_->is_in_storage(path);
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);
262 fs::path
const& path = fs::path(),
263 unsigned* counter =
nullptr)
override {
264 return collector_->scan_for_files(method, path, counter);
268 symlink_paths_.emplace_back(std::move(symlink_path));
273 boost::log::formatting_ostream& strm,
274 boost::log::to_log_manip<Channel, tag::channel>
const& manip) {
279 boost::log::formatting_ostream& strm,
280 boost::log::to_log_manip<Severity, tag::severity>
const& manip) {
284 template <
typename TAG,
typename SINK>
286 if constexpr (std::is_same<TAG, Channel>::value) {
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);
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);
303 template <
typename FILE_SINK,
typename TAG>
304 boost::shared_ptr<FILE_SINK>
make_sink(boost::shared_ptr<Collector>& collector,
306 fs::path
const& full_log_dir,
308 auto sink = boost::make_shared<FILE_SINK>(
309 keywords::file_name =
313 if constexpr (std::is_same<TAG, Channel>::value) {
314 sink->set_filter(channel == static_cast<Channel>(tag));
315 set_formatter<Channel>(sink);
320 : static_cast<Severity>(tag);
321 sink->set_filter(min_filter_level <= severity);
322 set_formatter<Severity>(sink);
324 typename FILE_SINK::locked_backend_ptr backend = sink->locked_backend();
326 backend->set_time_based_rotation(sinks::file::rotation_at_time_point(0, 0, 0));
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();
340 using ClogSync = sinks::synchronous_sink<sinks::text_ostream_backend>;
341 using FileSync = sinks::synchronous_sink<sinks::text_file_backend>;
343 template <
typename CONSOLE_SINK>
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);
349 set_formatter<Severity>(sink);
361 boost::shared_ptr<boost::log::core> core = boost::log::core::get();
363 core->add_global_attribute(
"TimeStamp", attr::local_clock());
364 core->add_global_attribute(
"ProcessID", attr::current_process_id());
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);
373 core->add_sink(make_sink<FileSync>(collector, log_opts, full_log_dir, level));
376 if (log_dir_was_created) {
377 LOG(
INFO) <<
"Log directory(" << full_log_dir.native() <<
") created.";
379 for (
auto const channel : log_opts.
channels_) {
380 core->add_sink(make_sink<FileSync>(collector, log_opts, full_log_dir, channel));
384 core->add_sink(make_sink<ClogSync>(log_opts));
392 throw std::runtime_error(
393 "logger::set_once_fatal_func() should not be called more than once.");
398 static std::once_flag logger_flag;
399 std::call_once(logger_flag, []() {
400 boost::log::core::get()->remove_all_sinks();
410 if (1 < str.size() && (str.front() ==
'\'' || str.front() ==
'"') &&
411 str.front() == str.back()) {
412 str.erase(str.size() - 1, 1);
422 std::getline(in, line);
424 std::regex
const rex(R
"(\w+)");
425 using TokenItr = std::regex_token_iterator<std::string::iterator>;
427 for (TokenItr tok(line.begin(), line.end(), rex); tok != end; ++tok) {
430 in.setstate(std::ios_base::failbit);
433 channels.emplace(static_cast<Channel>(itr -
ChannelNames.cbegin()));
442 for (
auto const channel : channels) {
453 auto itr = std::find(SeverityNames.cbegin(), SeverityNames.cend(), token);
454 if (itr == SeverityNames.cend()) {
455 in.setstate(std::ios_base::failbit);
457 sev =
static_cast<Severity>(itr - SeverityNames.cbegin());
464 return out << SeverityNames.at(sev);
477 return gChannelLogger_IR::get();
479 return gChannelLogger_PTX::get();
481 return gChannelLogger_ASM::get();
488 , enum_value_(channel)
489 , record_(std::make_unique<boost::log::record>(
492 stream_ = std::make_unique<boost::log::record_ostream>(*record_);
498 , enum_value_(severity)
499 , record_(std::make_unique<boost::log::record>(
500 gSeverityLogger::get().open_record(keywords::severity = severity))) {
502 stream_ = std::make_unique<boost::log::record_ostream>(*record_);
510 .push_record(boost::move(
stream_->get_record()));
512 gSeverityLogger::get().push_record(boost::move(
stream_->get_record()));
526 Logger::operator bool()
const {
527 return static_cast<bool>(stream_);
555 using Clock = std::chrono::steady_clock;
584 template <
typename Units = std::chrono::milliseconds>
587 template <
typename Units = std::chrono::milliseconds>
588 typename Units::rep
value()
const;
614 return boost::get<Duration>(
durations_.front());
621 return boost::get<Duration>(&
durations_.back());
628 stop_ = Clock::now();
633 template <
typename Units>
638 template <
typename Units>
640 return std::chrono::duration_cast<Units>(
stop_ -
start_).count();
658 if (!duration_tree_ptr) {
662 return duration_tree_ptr->newDuration(debug_timer_params);
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.";
673 return os << std::setw(2 * duration.
depth_) <<
' ' << duration.
value() <<
"ms start("
679 os << std::setw(2 * duration_tree.
depth_) <<
' ' <<
"New thread("
681 for (
auto const& duration_tree_node : duration_tree.
durations()) {
682 os <<
'\n' << duration_tree_node;
685 << std::setw(2 * duration_tree.
depth_) <<
' ' <<
"End thread("
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) {
710 std::shared_ptr<rapidjson::Document>
doc_;
711 rapidjson::Document::AllocatorType&
alloc_;
713 DurationTreeNodes::const_iterator
begin_;
714 DurationTreeNodes::const_iterator
end_;
717 DurationTreeNodes::const_iterator begin,
718 DurationTreeNodes::const_iterator end)
723 :
doc_(std::make_shared<rapidjson::Document>(rapidjson::kObjectType))
726 rapidjson::Value retval(rapidjson::kObjectType);
727 retval.AddMember(
"type",
"duration",
alloc_);
728 retval.AddMember(
"duration_ms", rapidjson::Value(duration.
value()),
alloc_);
731 retval.AddMember(
"name", rapidjson::StringRef(duration->
name_),
alloc_);
733 retval.AddMember(
"line", rapidjson::Value(duration->
line_),
alloc_);
740 rapidjson::Value retval(rapidjson::kObjectType);
741 retval.AddMember(
"type",
"duration_tree",
alloc_);
748 rapidjson::Value children(rapidjson::kArrayType);
750 int const depth = apply_visitor(get_depth, *itr);
751 if (depth <= parent_depth) {
754 if (depth == parent_depth + 1) {
756 children.PushBack(apply_visitor(json_encoder, *itr),
alloc_);
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);
768 auto const& root_duration = boost::get<Duration>(*(
begin_++));
769 retval.AddMember(
"type",
"root",
alloc_);
772 "total_duration_ms", rapidjson::Value(root_duration.value()),
alloc_);
773 retval.AddMember(
"name", rapidjson::StringRef(root_duration->name_),
alloc_);
779 std::string
str(DurationTreeMap::const_reference kv_pair) {
781 rapidjson::StringBuffer buffer;
782 rapidjson::Writer<rapidjson::StringBuffer> writer(buffer);
783 doc_->Accept(writer);
784 return {buffer.GetString(), buffer.GetSize()};
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);
798 for (
auto const& duration_tree_node : duration_tree.
durations()) {
799 apply_visitor(*
this, duration_tree_node);
807 DurationTreeMap::const_iterator
const itr =
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;
816 *json_str = json_encoder.
str(*itr);
819 erase_duration_trees(itr);
859 auto const current_depth = parent_itr->second->currentDepth();
864 <<
" already in map.";
865 parent_itr->second->pushDurationTree(*emplaced.first->second);
903 #endif // #ifndef __CUDACC__
std::istream & operator>>(std::istream &in, Channels &channels)
DurationTreeNodes::const_iterator end_
std::lock_guard< T > lock_guard
void track_symlink(fs::path symlink_path)
void pushDurationTree(DurationTree &duration_tree)
std::atomic< RequestId > g_next_request_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
ThreadLocalIds thread_local_ids_
void set_formatter(SINK &sink)
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_
bool g_enable_debug_timer
void operator()(Duration const &) const
const std::string kDefaultLogDirName
const std::string json_str(const rapidjson::Value &obj) noexcept
ThreadLocalIds prev_local_ids_
DurationTreeNodes durations_
std::vector< fs::path > symlink_paths_
void operator()(DurationTree const &duration_tree) const
fs::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
thread_local ThreadLocalIds g_thread_local_ids(0, 0)
Clock::time_point const start_
rapidjson::Value operator()(Duration const &duration)
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_
DebugTimerParams const * operator->() const
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
Duration(DurationTree *const duration_tree, int const depth, DebugTimerParams const debug_timer_params)
Severity g_min_active_severity
void store_file(fs::path const &path) override
std::atomic< FatalFunc > g_fatal_func
void debug_timer_new_thread(ThreadId const parent_thread_id)
int operator()(Duration const &duration) const
RequestId set_new_request_id()
ChannelLogger & get_channel_logger(Channel const channel)
DEVICE auto accumulate(ARGS &&...args)
void set_request_id(RequestId const request_id)
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::atomic< ThreadId > g_next_thread_id
uintmax_t scan_for_files(sinks::file::scan_method method, fs::path const &path=fs::path(), unsigned *counter=nullptr) override
static fs::path g_log_dir_path
std::unique_ptr< boost::log::record_ostream > stream_
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)
Duration * newDuration(DebugTimerParams const debug_timer_params)
LocalIdsScopeGuard setNewThreadId() const
boost::log::formatting_ostream & operator<<(boost::log::formatting_ostream &strm, boost::log::to_log_manip< Channel, tag::channel > const &manip)
constexpr std::array< char const *, 8 > SeverityNames
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)
std::string file_name_pattern_
bool g_enable_watchdog false
int operator()(DurationTree const &duration_tree) const
DurationTreeMap g_duration_tree_map
boost::filesystem::path full_log_dir() const
Duration * newDuration(DebugTimerParams const debug_timer_params)
std::chrono::steady_clock Clock
void unquote(std::string &str)
Collector(fs::path const &full_log_dir, LogOptions const &log_opts)
std::shared_ptr< rapidjson::Document > doc_
boost::variant< Duration, DurationTree & > DurationTreeNode
boost::shared_ptr< sinks::file::collector > collector_
ThreadLocalIds thread_local_ids()
rapidjson::Document::AllocatorType & alloc_
DebugTimerParams const debug_timer_params_
boost::log::record_ostream & stream(char const *file, int line)