Unverified Commit 1045d515 authored by Mccaskey, Alex's avatar Mccaskey, Alex Committed by GitHub
Browse files

Merge pull request #208 from tnguyen-ornl/tnguyen/log

Added file logging and util timer
parents a8b8bf5d f43df9d3
Pipeline #107459 passed with stage
in 23 minutes and 21 seconds
......@@ -18,7 +18,9 @@
#include <iostream>
#include <sstream>
#include <istream>
#include <iomanip>
#include <dirent.h>
#include "xacc_config.hpp"
#ifdef HAS_LIBUNWIND
#include <libunwind.h>
......@@ -62,6 +64,21 @@ bool directoryExists(const std::string path) {
return bExists;
}
bool makeDirectory(const std::string& path) {
int ret = mkdir(path.c_str(), S_IRWXU | S_IRGRP | S_IXGRP | S_IROTH | S_IXOTH);
return (ret == 0);
}
std::string getCurrentTimeForFileName() {
auto time = std::time(nullptr);
std::stringstream ss;
// ISO 8601 without timezone information.
ss << std::put_time(std::localtime(&time), "%F_%T");
auto s = ss.str();
std::replace(s.begin(), s.end(), ':', '-');
return s;
}
void print_backtrace() {
#ifdef HAS_LIBUNWIND
unw_cursor_t cursor;
......@@ -164,19 +181,102 @@ void trim(std::string &s) {
}
XACCLogger::XACCLogger()
: useColor(!RuntimeOptions::instance()->exists("no-color")),
useCout(RuntimeOptions::instance()->exists("use-cout")) {
useCout(RuntimeOptions::instance()->exists("use-cout")),
useFile(RuntimeOptions::instance()->exists("use-file")) {
// Create a std::out logger instance
std::string loggerName = "xacc-logger";
if (RuntimeOptions::instance()->exists("logger-name")) {
loggerName = (*RuntimeOptions::instance())["logger-name"];
}
auto _log = spdlog::get(loggerName);
if (_log) {
logger = _log;
stdOutLogger = _log;
} else {
stdOutLogger = spdlog::stdout_logger_mt(loggerName);
}
stdOutLogger->set_level(spdlog::level::info);
}
void XACCLogger::createFileLogger() {
// Create a file logger instance
std::string loggerName = "xacc-file-logger";
auto _log = spdlog::get(loggerName);
if (_log) {
fileLogger = _log;
} else {
logger = spdlog::stdout_logger_mt(loggerName);
const std::string rootPath(XACC_INSTALL_DIR);
// We'll put the log file (timestamped) to the "logs" sub-directory:
std::string logDir = rootPath + "/logs";
if (!directoryExists(logDir)) {
if (!makeDirectory(logDir)) {
// Cannot make the directory, use the current directory instead.
logDir = "";
}
}
const std::string DEFAULT_FILE_NAME_PREFIX = "xacc_log_";
const std::string DEFAULT_FILE_NAME_POSTFIX = ".txt";
const std::string fileName = DEFAULT_FILE_NAME_PREFIX + getCurrentTimeForFileName() + DEFAULT_FILE_NAME_POSTFIX;
// Create a file logger using the timestamped filename in the logs folder.
fileLogger = spdlog::basic_logger_mt(loggerName, logDir + "/" + fileName);
}
fileLogger->set_level(spdlog::level::info);
}
void XACCLogger::logToFile(bool enable) {
// Switching the current setting
if (enable != useFile) {
// Always dump any enqueued messages before switching.
dumpQueue();
// Set runtime *useFile* flag, this will redirect
// log message to the appropriate logger.
useFile = enable;
}
}
void XACCLogger::setLoggingLevel(int level) {
if (level < 0 || level > 2) {
// Ignored
return;
}
// Converted the level to the spd-log enum
if (level == 0) {
// Warning and above
getLogger()->set_level(spdlog::level::warn);
}
if (level == 1) {
// Info and above
getLogger()->set_level(spdlog::level::info);
}
logger->set_level(spdlog::level::info);
if (level == 2) {
// Debug and above
getLogger()->set_level(spdlog::level::debug);
}
// Notify subscribers
for (const auto& callback : loggingLevelSubscribers) {
try {
callback(level);
}
catch (...) {
// Do nothing. This is to prevent any rogue subscribers.
}
}
}
int XACCLogger::getLoggingLevel() {
const auto spdLevel = getLogger()->level();
switch (spdLevel) {
case spdlog::level::trace:
case spdlog::level::debug: return 2;
case spdlog::level::info: return 1;
default:
return 0;
}
}
void XACCLogger::info(const std::string &msg, MessagePredicate predicate) {
......@@ -190,10 +290,10 @@ void XACCLogger::info(const std::string &msg, MessagePredicate predicate) {
}
} else {
if (predicate() && globalPredicate()) {
if (useColor) {
logger->info("\033[1;34m" + msg + "\033[0m");
if (useColor & !useFile) {
getLogger()->info("\033[1;34m" + msg + "\033[0m");
} else {
logger->info(msg);
getLogger()->info(msg);
}
}
}
......@@ -210,10 +310,10 @@ void XACCLogger::warning(const std::string &msg, MessagePredicate predicate) {
}
} else {
if (predicate() && globalPredicate()) {
if (useColor) {
logger->info("\033[1;33m" + msg + "\033[0m");
if (useColor & !useFile) {
getLogger()->info("\033[1;33m" + msg + "\033[0m");
} else {
logger->info(msg);
getLogger()->info(msg);
}
}
}
......@@ -230,10 +330,10 @@ void XACCLogger::debug(const std::string &msg, MessagePredicate predicate) {
}
} else {
if (predicate() && globalPredicate()) {
if (useColor) {
logger->info("\033[1;32m" + msg + "\033[0m");
if (useColor & !useFile) {
getLogger()->info("\033[1;32m" + msg + "\033[0m");
} else {
logger->info(msg);
getLogger()->info(msg);
}
}
}
......@@ -244,9 +344,30 @@ void XACCLogger::error(const std::string &msg, MessagePredicate predicate) {
std::cerr << msg << "\n";
} else {
if (predicate() && globalPredicate()) {
logger->error("\033[1;31m[XACC Error] " + msg + "\033[0m");
getLogger()->error("\033[1;31m[XACC Error] " + msg + "\033[0m");
}
}
}
ScopeTimer::ScopeTimer(const std::string& scopeName, bool shouldLog):
m_startTime(std::chrono::system_clock::now()),
m_shouldLog(shouldLog),
m_scopeName(scopeName)
{
if (m_shouldLog) {
XACCLogger::instance()->info("'" + scopeName + "' started.");
}
}
double ScopeTimer::getDurationMs() const {
return static_cast<double>(
std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::system_clock::now() - m_startTime).count()/1000.0);
}
ScopeTimer::~ScopeTimer() {
const double elapsedTime = getDurationMs();
if (m_shouldLog) {
XACCLogger::instance()->info("'" + m_scopeName + "' finished [" + std::to_string(elapsedTime) + " ms].");
}
}
} // namespace xacc
......@@ -21,6 +21,7 @@
#include <sstream>
#include <algorithm>
#include <map>
#include <chrono>
namespace spdlog {
class logger;
......@@ -139,21 +140,46 @@ void tuple_for_each(TupleType &&t, FunctionType f) {
}
using MessagePredicate = std::function<bool(void)>;
// Notify subscribers when the logging level was changed.
// This can be used to control logging level/verbosity of
// external libraries (e.g. those used by plugins) to
// match that of XACC.
using LoggingLevelNotification = std::function<void(int)>;
class XACCLogger : public Singleton<XACCLogger> {
protected:
std::shared_ptr<spdlog::logger> logger;
std::shared_ptr<spdlog::logger> stdOutLogger;
std::shared_ptr<spdlog::logger> fileLogger;
bool useCout = false;
// Should we log to file?
bool useFile = false;
bool useColor = true;
MessagePredicate globalPredicate = []() { return true; };
std::vector<LoggingLevelNotification> loggingLevelSubscribers;
std::queue<std::string> logQueue;
XACCLogger();
std::shared_ptr<spdlog::logger> getLogger() {
static bool fileLoggerUsed = false;
if (!fileLoggerUsed && useFile) {
createFileLogger();
fileLoggerUsed = true;
}
return useFile ? fileLogger : stdOutLogger;
}
// On-demand create a file logger:
// We don't want to create one if not being used.
void createFileLogger();
public:
// Overriding here so we can have a custom constructor
......@@ -164,6 +190,23 @@ public:
return instance_;
}
// If enable = true, switch to File logging (if not already logging to file).
// If enable = false, stop logging to File if currently is.
// This enables dev to scope a section which should log to File.
void logToFile(bool enable);
// Set level for log filtering:
// 0: Errors and Warnings only
// 1: Info and above
// 2: Debug and above
// Note: this will only take effect when xacc::verbose is set.
void setLoggingLevel(int level);
int getLoggingLevel();
void subscribeLoggingLevel(LoggingLevelNotification onLevelChangeFn) {
loggingLevelSubscribers.emplace_back(onLevelChangeFn);
}
void enqueueLog(const std::string log) { logQueue.push(log); }
void dumpQueue() {
......@@ -204,6 +247,40 @@ template <typename T> std::vector<T> linspace(T a, T b, size_t N) {
return xs;
}
// Util timer to log execution elapsed time of a scope block.
// Example usage:
// (1) Time a function body:
/*
void slowFunc {
// Use __FUNCTION__ macro to get the function name
// Can use a custom string as well
ScopeTimer timer(__FUNCTION__);
.... code
}
*/
// The above timer will log when the function starts and ends (with elapsed time).
// (2) Time a code block, including function calls
/*
... irrelevant code
// Create a scope block:
{
ScopeTimer timer("human readable name of this block");
.... code
}
... irrelevant code
*/
// This will log the timing data of that specific code block.
class ScopeTimer {
public:
ScopeTimer(const std::string& scopeName, bool shouldLog = true);
double getDurationMs() const;
~ScopeTimer();
private:
std::chrono::time_point<std::chrono::system_clock> m_startTime;
bool m_shouldLog;
std::string m_scopeName;
};
// container helper
namespace container {
template<typename ContainerType, typename ElementType>
......
......@@ -111,6 +111,22 @@ void setGlobalLoggerPredicate(MessagePredicate predicate) {
XACCLogger::instance()->dumpQueue();
}
void logToFile(bool enable) {
XACCLogger::instance()->logToFile(enable);
}
void setLoggingLevel(int level) {
XACCLogger::instance()->setLoggingLevel(level);
}
int getLoggingLevel() {
return XACCLogger::instance()->getLoggingLevel();
}
void subscribeLoggingLevel(LoggingLevelNotification callback) {
XACCLogger::instance()->subscribeLoggingLevel(callback);
}
void info(const std::string &msg, MessagePredicate predicate) {
if (verbose) XACCLogger::instance()->info(msg, predicate);
}
......
......@@ -95,6 +95,11 @@ void addCommandLineOptions(const std::string &category,
void addCommandLineOptions(const std::map<std::string, std::string> &options);
void setGlobalLoggerPredicate(MessagePredicate predicate);
void logToFile(bool enable);
void setLoggingLevel(int level);
int getLoggingLevel();
void subscribeLoggingLevel(LoggingLevelNotification callback);
void info(const std::string &msg,
MessagePredicate predicate = std::function<bool(void)>([]() {
return true;
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment