Skip to content

Commit

Permalink
Logger: Remove stringstream in total (#4484)
Browse files Browse the repository at this point in the history 
close #2179, close #4346
  • Loading branch information
@JaySon-Huang
JaySon-Huang authored Mar 30, 2022
1 parent aa62633 commit a1b2035
Show file tree
Hide file tree
Showing 9 changed files with 167 additions and 180 deletions.
33 changes: 21 additions & 12 deletions dbms/src/Client/Connection.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@
#include <Common/ClickHouseRevision.h>
#include <Common/CurrentMetrics.h>
#include <Common/Exception.h>
#include <Common/FmtUtils.h>
#include <Common/NetException.h>
#include <Common/config.h>
#include <Core/Defines.h>
Expand Down Expand Up @@ -451,21 +452,29 @@ void Connection::sendExternalTablesData(ExternalTablesData & data)

out_bytes = out->count() - out_bytes;
maybe_compressed_out_bytes = maybe_compressed_out->count() - maybe_compressed_out_bytes;
double elapsed = watch.elapsedSeconds();

std::stringstream msg;
msg << std::fixed << std::setprecision(3);
msg << "Sent data for " << data.size() << " external tables, total " << rows << " rows in " << elapsed << " sec., "
<< static_cast<size_t>(rows / watch.elapsedSeconds()) << " rows/sec., "
<< maybe_compressed_out_bytes / 1048576.0 << " MiB (" << maybe_compressed_out_bytes / 1048576.0 / watch.elapsedSeconds() << " MiB/sec.)";
auto get_logging_msg = [&]() -> String {
const double elapsed_seconds = watch.elapsedSeconds();

if (compression == Protocol::Compression::Enable)
msg << ", compressed " << static_cast<double>(maybe_compressed_out_bytes) / out_bytes << " times to "
<< out_bytes / 1048576.0 << " MiB (" << out_bytes / 1048576.0 / watch.elapsedSeconds() << " MiB/sec.)";
else
msg << ", no compression.";
FmtBuffer fmt_buf;
fmt_buf.fmtAppend(
"Sent data for {} external tables, total {} rows in {:.3f} sec., {:.3f} rows/sec., "
"{:.3f} MiB ({:.3f} MiB/sec.)",
data.size(),
rows,
elapsed_seconds,
1.0 * rows / elapsed_seconds,
maybe_compressed_out_bytes / 1048576.0,
maybe_compressed_out_bytes / 1048576.0 / elapsed_seconds);

if (compression == Protocol::Compression::Enable)
fmt_buf.fmtAppend(", compressed {:.3f} times to {:.3f} MiB ({:.3f} MiB/sec.)", 1.0 * maybe_compressed_out_bytes / out_bytes, out_bytes / 1048576.0, out_bytes / 1048576.0 / elapsed_seconds);
else
fmt_buf.append(", no compression.");
return fmt_buf.toString();
};

LOG_DEBUG(log_wrapper.get(), msg.rdbuf());
LOG_DEBUG(log_wrapper.get(), get_logging_msg());
}


Expand Down
8 changes: 4 additions & 4 deletions dbms/src/Storages/DeltaMerge/WriteBatches.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -62,10 +62,10 @@ struct WriteBatches : private boost::noncopyable
if (!wb.empty())
{
StackTrace trace;
LOG_ERROR(logger,
"!!!=========================Modifications in " + name
+ " haven't persisted=========================!!! Stack trace: "
<< trace.toString());
LOG_FMT_ERROR(logger,
"!!!=========================Modifications in {} haven't persisted=========================!!! Stack trace: {}",
name,
trace.toString());
}
};
check_empty(log, "log");
Expand Down
83 changes: 24 additions & 59 deletions libs/libcommon/include/common/logger_useful.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,69 +19,10 @@
#include <Poco/Logger.h>
#include <fmt/format.h>

#include <sstream>

#ifndef QUERY_PREVIEW_LENGTH
#define QUERY_PREVIEW_LENGTH 160
#endif

/// Logs a message to a specified logger with that level.

#define LOG_TRACE(logger, message) \
do \
{ \
if ((logger)->trace()) \
{ \
std::stringstream oss_internal_rare; \
oss_internal_rare << message; \
(logger)->trace(oss_internal_rare.str()); \
} \
} while (false)

#define LOG_DEBUG(logger, message) \
do \
{ \
if ((logger)->debug()) \
{ \
std::stringstream oss_internal_rare; \
oss_internal_rare << message; \
(logger)->debug(oss_internal_rare.str()); \
} \
} while (false)

#define LOG_INFO(logger, message) \
do \
{ \
if ((logger)->information()) \
{ \
std::stringstream oss_internal_rare; \
oss_internal_rare << message; \
(logger)->information(oss_internal_rare.str()); \
} \
} while (false)

#define LOG_WARNING(logger, message) \
do \
{ \
if ((logger)->warning()) \
{ \
std::stringstream oss_internal_rare; \
oss_internal_rare << message; \
(logger)->warning(oss_internal_rare.str()); \
} \
} while (false)

#define LOG_ERROR(logger, message) \
do \
{ \
if ((logger)->error()) \
{ \
std::stringstream oss_internal_rare; \
oss_internal_rare << message; \
(logger)->error(oss_internal_rare.str()); \
} \
} while (false)

namespace LogFmtDetails
{
template <typename... Ts>
Expand Down Expand Up @@ -118,6 +59,30 @@ std::string toCheckedFmtStr(const S & format, const Ignored &, Args &&... args)
}
} // namespace LogFmtDetails

/// Logs a message to a specified logger with that level.

#define LOG_IMPL(logger, PRIORITY, message) \
do \
{ \
if ((logger)->is((PRIORITY))) \
{ \
Poco::Message poco_message( \
/*source*/ (logger)->name(), \
/*text*/ message, \
/*prio*/ (PRIORITY), \
/*file*/ &__FILE__[LogFmtDetails::getFileNameOffset(__FILE__)], \
/*line*/ __LINE__); \
(logger)->log(poco_message); \
} \
} while (false)

#define LOG_TRACE(logger, message) LOG_IMPL(logger, Poco::Message::PRIO_TRACE, message)
#define LOG_DEBUG(logger, message) LOG_IMPL(logger, Poco::Message::PRIO_DEBUG, message)
#define LOG_INFO(logger, message) LOG_IMPL(logger, Poco::Message::PRIO_INFORMATION, message)
#define LOG_WARNING(logger, message) LOG_IMPL(logger, Poco::Message::PRIO_WARNING, message)
#define LOG_ERROR(logger, message) LOG_IMPL(logger, Poco::Message::PRIO_ERROR, message)
#define LOG_FATAL(logger, message) LOG_IMPL(logger, Poco::Message::PRIO_FATAL, message)


/// Logs a message to a specified logger with that level.
/// If more than one argument is provided,
Expand Down
12 changes: 12 additions & 0 deletions libs/libcommon/src/tests/gtest_logger.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -59,6 +59,13 @@ TEST_F(LoggerUsefulTest, Log)
LOG_INFO(log, "Info log");
LOG_WARNING(log, "Warning log");
LOG_ERROR(log, "Error log");

// Do not accept more than one parameter
// LOG_ERROR(log, "Error log, num: ", 1);

std::string msg_in_log;
msg_in_log = "hello tiflash";
LOG_DEBUG(log, msg_in_log);
}

TEST_F(LoggerUsefulTest, LogFmt)
Expand All @@ -69,6 +76,11 @@ TEST_F(LoggerUsefulTest, LogFmt)
LOG_FMT_INFO(log, "Info log");
LOG_FMT_WARNING(log, "Warning log");
LOG_FMT_ERROR(log, "Error log");

// Error! Do not accept a variable as format string.
// std::string msg_in_log;
// msg_in_log = "hello tiflash";
// LOG_FMT_DEBUG(log, msg_in_log);
}

} // namespace tests
92 changes: 41 additions & 51 deletions libs/libdaemon/include/daemon/BaseDaemon.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -40,28 +40,20 @@
#include <mutex>
#include <optional>

/// \brief Базовый класс для демонов
/// \brief Base class for applications that can run as daemons.
///
/// \code
/// # Список возможных опций командной строки обрабатываемых демоном:
/// # --config-file или --config - имя файла конфигурации. По умолчанию - config.xml
/// # --pid-file - имя PID файла. По умолчанию - pid
/// # --log-file - имя лог файла
/// # --error-file - имя лог файла, в который будут помещаться только ошибки
/// # --daemon - запустить в режиме демона; если не указан - логгирование будет вестись на консоль
/// <daemon_name> --daemon --config-file=localfile.xml --pid-file=pid.pid --log-file=log.log --errorlog-file=error.log
/// # Some possible command line options:
/// # --config-file, -C or --config - path to configuration file. By default - config.xml in the current directory.
/// # --pid-file - PID file name. Default is pid
/// # --log-file
/// # --errorlog-file
/// # --daemon - run as daemon; without this option, the program will be attached to the terminal and also output logs to stderr.
/// <daemon_name> --daemon --config-file=localfile.xml --log-file=log.log --errorlog-file=error.log
/// \endcode
///
/// Если неперехваченное исключение выкинуто в других потоках (не Task-и), то по-умолчанию
/// используется KillingErrorHandler, который вызывает std::terminate.
///
/// Кроме того, класс позволяет достаточно гибко управлять журналированием. В методе initialize() вызывается метод
/// buildLoggers() который и строит нужные логгеры. Эта функция ожидает увидеть в конфигурации определённые теги
/// заключённые в секции "logger".
/// Если нужно журналирование на консоль, нужно просто не использовать тег "log" или использовать --console.
/// Теги уровней вывода использовать можно в любом случае


/// You can configure different log options for different loggers used inside program
/// by providing subsections to "logger" in configuration file.
class BaseDaemon : public Poco::Util::ServerApplication
{
friend class SignalListener;
Expand All @@ -72,31 +64,30 @@ class BaseDaemon : public Poco::Util::ServerApplication
BaseDaemon();
~BaseDaemon();

/// Загружает конфигурацию и "строит" логгеры на запись в файлы
/// Load configuration, prepare loggers, etc.
void initialize(Poco::Util::Application &) override;

/// Читает конфигурацию
/// Reads the configuration
void reloadConfiguration();

/// Строит необходимые логгеры
/// Builds the necessary loggers
void buildLoggers(Poco::Util::AbstractConfiguration & config);

/// Определяет параметр командной строки
/// Process command line parameters
void defineOptions(Poco::Util::OptionSet & _options) override;

/// Завершение демона ("мягкое")
/// Graceful shutdown
void terminate();

/// Завершение демона ("жёсткое")
/// Forceful shutdown
void kill();

/// Получен ли сигнал на завершение?
/// Cancellation request has been received.
bool isCancelled() const
{
return is_cancelled;
}

/// Получение ссылки на экземпляр демона
static BaseDaemon & instance()
{
return dynamic_cast<BaseDaemon &>(Poco::Util::Application::instance());
Expand All @@ -105,39 +96,38 @@ class BaseDaemon : public Poco::Util::ServerApplication
/// return none if daemon doesn't exist, reference to the daemon otherwise
static std::optional<std::reference_wrapper<BaseDaemon>> tryGetInstance() { return tryGetInstance<BaseDaemon>(); }

/// Спит заданное количество секунд или до события wakeup
/// Sleeps for the set number of seconds or until wakeup event
void sleep(double seconds);

/// Разбудить
void wakeup();

/// Закрыть файлы с логами. При следующей записи, будут созданы новые файлы.
/// Close the log files. The next time you write, new files will be created.
void closeLogs();

/// В Graphite компоненты пути(папки) разделяются точкой.
/// У нас принят путь формата root_path.hostname_yandex_ru.key
/// root_path по умолчанию one_min
/// key - лучше группировать по смыслу. Например "meminfo.cached" или "meminfo.free", "meminfo.total"
/// In Graphite, path(folder) components are separated by a dot.
/// We have adopted the format root_path.hostname_yandex_ru.key
/// root_path is by default one_min
/// key - better to group by meaning. For example "meminfo.cached" or "meminfo.free", "meminfo.total"
template <class T>
void writeToGraphite(const std::string & key, const T & value, const std::string & config_name = DEFAULT_GRAPHITE_CONFIG_NAME, time_t timestamp = 0, const std::string & custom_root_path = "")
{
auto writer = getGraphiteWriter(config_name);
auto * writer = getGraphiteWriter(config_name);
if (writer)
writer->write(key, value, timestamp, custom_root_path);
}

template <class T>
void writeToGraphite(const GraphiteWriter::KeyValueVector<T> & key_vals, const std::string & config_name = DEFAULT_GRAPHITE_CONFIG_NAME, time_t timestamp = 0, const std::string & custom_root_path = "")
{
auto writer = getGraphiteWriter(config_name);
auto * writer = getGraphiteWriter(config_name);
if (writer)
writer->write(key_vals, timestamp, custom_root_path);
}

template <class T>
void writeToGraphite(const GraphiteWriter::KeyValueVector<T> & key_vals, const std::chrono::system_clock::time_point & current_time, const std::string & custom_root_path)
{
auto writer = getGraphiteWriter();
auto * writer = getGraphiteWriter();
if (writer)
writer->write(key_vals, std::chrono::system_clock::to_time_t(current_time), custom_root_path);
}
Expand All @@ -151,21 +141,21 @@ class BaseDaemon : public Poco::Util::ServerApplication

std::optional<size_t> getLayer() const
{
return layer; /// layer выставляется в классе-наследнике BaseDaemonApplication.
return layer;
}

protected:
virtual void logRevision() const;

/// Используется при exitOnTaskError()
/// Used when exitOnTaskError()
void handleNotification(Poco::TaskFailedNotification *);

/// thread safe
virtual void handleSignal(int signal_id);

/// реализация обработки сигналов завершения через pipe не требует блокировки сигнала с помощью sigprocmask во всех потоках
/// implementation of pipe termination signal handling does not require blocking the signal with sigprocmask in all threads
void waitForTerminationRequest()
#if POCO_CLICKHOUSE_PATCH || POCO_VERSION >= 0x02000000 // in old upstream poco not vitrual
#if POCO_CLICKHOUSE_PATCH || POCO_VERSION >= 0x02000000 // in old upstream poco not virtual
override
#endif
;
Expand All @@ -177,21 +167,21 @@ class BaseDaemon : public Poco::Util::ServerApplication

virtual std::string getDefaultCorePath() const;

/// Создание и автоматическое удаление pid файла.
/// Creation and automatic deletion of a pid file.
struct PID
{
std::string file;

/// Создать объект, не создавая PID файл
PID() {}
/// Create an object without creating a PID file
PID() = default;

/// Создать объект, создать PID файл
PID(const std::string & file_) { seed(file_); }
/// Create object, create PID file
explicit PID(const std::string & file_) { seed(file_); }

/// Создать PID файл
/// Create a PID file
void seed(const std::string & file_);

/// Удалить PID файл
/// Delete PID file
void clear();

~PID() { clear(); }
Expand All @@ -201,19 +191,19 @@ class BaseDaemon : public Poco::Util::ServerApplication

std::atomic_bool is_cancelled{false};

/// Флаг устанавливается по сообщению из Task (при аварийном завершении).
/// The flag is set by a message from Task (in case of an emergency stop).
bool task_failed = false;

bool log_to_console = false;

/// Событие, чтобы проснуться во время ожидания
/// An event to wake up to while waiting
Poco::Event wakeup_event;

/// Поток, в котором принимается сигнал HUP/USR1 для закрытия логов.
/// The stream in which the HUP/USR1 signal is received to close the logs.
Poco::Thread signal_listener_thread;
std::unique_ptr<Poco::Runnable> signal_listener;

/// Файлы с логами.
/// Log files.
Poco::AutoPtr<Poco::FileChannel> log_file;
Poco::AutoPtr<Poco::FileChannel> error_log_file;
Poco::AutoPtr<Poco::FileChannel> tracing_log_file;
Expand Down
Loading

0 comments on commit a1b2035

Please sign in to comment.