From eec1a3eb89a40d7b2a1efd42db1d2e687e4e4a27 Mon Sep 17 00:00:00 2001 From: Yuhong Guo Date: Fri, 24 Aug 2018 00:43:38 +0800 Subject: [PATCH] Support pluggable backend log lib with glog (#2695) * [WIP] Support different backend log lib * Refine code, unify level, address comment * Address comment and change formatter * Fix linux building failure. * Fix lint * Remove log4cplus. * Add log init to raylet main and add test to travis. * Address comment and refine. * Update logging_test.cc --- .travis.yml | 1 + CMakeLists.txt | 4 + cmake/Modules/ThirdpartyToolchain.cmake | 36 ++++++ src/common/redis_module/CMakeLists.txt | 5 +- src/ray/CMakeLists.txt | 14 ++- src/ray/raylet/main.cc | 2 + src/ray/util/CMakeLists.txt | 2 + src/ray/util/logging.cc | 140 ++++++++++++++++++++++++ src/ray/util/logging.h | 123 ++++++++++----------- src/ray/util/logging_test.cc | 79 +++++++++++++ 10 files changed, 339 insertions(+), 67 deletions(-) create mode 100644 src/ray/util/logging.cc create mode 100644 src/ray/util/logging_test.cc diff --git a/.travis.yml b/.travis.yml index 4177e6515..083f000de 100644 --- a/.travis.yml +++ b/.travis.yml @@ -182,6 +182,7 @@ install: - ./src/ray/raylet/lineage_cache_test - ./src/ray/raylet/task_dependency_manager_test - ./src/ray/raylet/reconstruction_policy_test + - ./src/ray/util/logging_test --gtest_filter=PrintLogTest* - bash ../src/common/test/run_tests.sh - bash ../src/plasma/test/run_tests.sh diff --git a/CMakeLists.txt b/CMakeLists.txt index 72ef6a91d..52d575b72 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -34,6 +34,10 @@ option(RAY_USE_NEW_GCS "Use the new GCS implementation" OFF) +option(RAY_USE_GLOG + "Build the logging system using glog" + ON) + if (RAY_USE_NEW_GCS) add_definitions(-DRAY_USE_NEW_GCS) endif() diff --git a/cmake/Modules/ThirdpartyToolchain.cmake b/cmake/Modules/ThirdpartyToolchain.cmake index 054727988..389a2a6aa 100644 --- a/cmake/Modules/ThirdpartyToolchain.cmake +++ b/cmake/Modules/ThirdpartyToolchain.cmake @@ -94,3 +94,39 @@ endif() set(Boost_USE_STATIC_LIBS ON) find_package(Boost COMPONENTS system filesystem REQUIRED) include_directories(${Boost_INCLUDE_DIR}) + +if(RAY_USE_GLOG) + message(STATUS "Starting to build glog") + set(GLOG_VERSION "0.3.5") + set(GLOG_CMAKE_CXX_FLAGS ${EP_CXX_FLAGS} "-fPIC") + + set(GLOG_URL "https://github.com/google/glog/archive/v${GLOG_VERSION}.tar.gz") + set(GLOG_PREFIX "${CMAKE_CURRENT_BINARY_DIR}/glog_ep-prefix/src/glog_ep") + set(GLOG_HOME "${GLOG_PREFIX}") + set(GLOG_INCLUDE_DIR "${GLOG_PREFIX}/include") + set(GLOG_STATIC_LIB "${GLOG_PREFIX}/lib/libglog.a") + + set(GLOG_CMAKE_ARGS -DCMAKE_BUILD_TYPE=${CMAKE_BUILD_TYPE} + -DCMAKE_INSTALL_PREFIX=${GLOG_PREFIX} + -DBUILD_SHARED_LIBS=OFF + -DBUILD_TESTING=OFF + -DWITH_GFLAGS=OFF + -DCMAKE_CXX_FLAGS_${UPPERCASE_BUILD_TYPE}=${GLOG_CMAKE_CXX_FLAGS} + -DCMAKE_C_FLAGS_${UPPERCASE_BUILD_TYPE}=${EP_C_FLAGS} + -DCMAKE_CXX_FLAGS=${GLOG_CMAKE_CXX_FLAGS}) + + ExternalProject_Add(glog_ep + URL ${GLOG_URL} + ${EP_LOG_OPTIONS} + BUILD_IN_SOURCE 1 + BUILD_BYPRODUCTS "${GLOG_STATIC_LIB}" + CMAKE_ARGS ${GLOG_CMAKE_ARGS}) + + message(STATUS "GLog include dir: ${GLOG_INCLUDE_DIR}") + message(STATUS "GLog static library: ${GLOG_STATIC_LIB}") + include_directories(SYSTEM ${GLOG_INCLUDE_DIR}) + ADD_THIRDPARTY_LIB(glog + STATIC_LIB ${GLOG_STATIC_LIB}) + + add_dependencies(glog glog_ep) +endif() diff --git a/src/common/redis_module/CMakeLists.txt b/src/common/redis_module/CMakeLists.txt index 53ce77d8d..f57d1c89e 100644 --- a/src/common/redis_module/CMakeLists.txt +++ b/src/common/redis_module/CMakeLists.txt @@ -14,4 +14,7 @@ endif() add_library(ray_redis_module SHARED ray_redis_module.cc) target_compile_options(ray_redis_module PUBLIC ${REDIS_MODULE_CFLAGS} -fPIC) -target_link_libraries(ray_redis_module ${REDIS_MODULE_LDFLAGS}) +target_link_libraries(ray_redis_module + # RAY_CHECK needs this lib. + LINK_PUBLIC ray_static + ${REDIS_MODULE_LDFLAGS}) diff --git a/src/ray/CMakeLists.txt b/src/ray/CMakeLists.txt index 7147c51b2..e2e2037ce 100644 --- a/src/ray/CMakeLists.txt +++ b/src/ray/CMakeLists.txt @@ -36,6 +36,7 @@ set(RAY_SRCS gcs/task_table.cc gcs/redis_context.cc gcs/asio.cc + util/logging.cc common/client_connection.cc object_manager/object_manager_client_connection.cc object_manager/connection_pool.cc @@ -61,6 +62,15 @@ set(RAY_SRCS raylet/raylet.cc ) +set(RAY_LIB_STATIC_LINK_LIBS ${PLASMA_STATIC_LIB} ${ARROW_STATIC_LIB}) +set(RAY_LIB_DEPENDENCIES gen_gcs_fbs gen_object_manager_fbs gen_node_manager_fbs gen_local_scheduler_fbs ${COMMON_FBS_OUTPUT_FILES}) + +if(RAY_USE_GLOG) + set(CMAKE_CXX_FLAGS "${CMAKE_CXX_FLAGS} -DRAY_USE_GLOG") + set(RAY_LIB_STATIC_LINK_LIBS ${RAY_LIB_STATIC_LINK_LIBS} ${GLOG_STATIC_LIB}) + set(RAY_LIB_DEPENDENCIES ${RAY_LIB_DEPENDENCIES} glog) +endif() + install(FILES api.h id.h @@ -79,6 +89,6 @@ ADD_RAY_LIB(ray SOURCES ${RAY_SRCS} ${AE_SRCS} ${HIREDIS_SRCS} ${UTIL_SRCS} # TODO: When raylet replaces the old backend, please remove the dependency gen_local_scheduler_fbs. # TODO: When remove the included Task.h from table.h, please remove the dependency gen_common_python_fbs. - DEPENDENCIES gen_gcs_fbs gen_object_manager_fbs gen_node_manager_fbs gen_local_scheduler_fbs ${COMMON_FBS_OUTPUT_FILES} + DEPENDENCIES ${RAY_LIB_DEPENDENCIES} SHARED_LINK_LIBS "" - STATIC_LINK_LIBS ${PLASMA_STATIC_LIB} ${ARROW_STATIC_LIB}) + STATIC_LINK_LIBS ${RAY_LIB_STATIC_LINK_LIBS}) diff --git a/src/ray/raylet/main.cc b/src/ray/raylet/main.cc index 3d5588508..dfb7be79b 100644 --- a/src/ray/raylet/main.cc +++ b/src/ray/raylet/main.cc @@ -6,6 +6,7 @@ #ifndef RAYLET_TEST int main(int argc, char *argv[]) { + RayLog::StartRayLog(argv[0], RAY_INFO); RAY_CHECK(argc == 10); const std::string raylet_socket_name = std::string(argv[1]); @@ -104,5 +105,6 @@ int main(int argc, char *argv[]) { signals.async_wait(handler); main_service.run(); + RayLog::ShutDownRayLog(); } #endif diff --git a/src/ray/util/CMakeLists.txt b/src/ray/util/CMakeLists.txt index a69896fff..bc06d3126 100644 --- a/src/ray/util/CMakeLists.txt +++ b/src/ray/util/CMakeLists.txt @@ -5,3 +5,5 @@ install(FILES visibility.h DESTINATION "${CMAKE_INSTALL_INCLUDEDIR}/ray/util" ) + +ADD_RAY_TEST(logging_test STATIC_LINK_LIBS ray_static gtest pthread) diff --git a/src/ray/util/logging.cc b/src/ray/util/logging.cc new file mode 100644 index 000000000..76663fb46 --- /dev/null +++ b/src/ray/util/logging.cc @@ -0,0 +1,140 @@ +#include +#include + +#include "ray/util/logging.h" + +#ifdef RAY_USE_GLOG +#include "glog/logging.h" +#endif + +namespace ray { + +// This is the default implementation of ray log, +// which is independent of any libs. +class CerrLog { + public: + CerrLog(int severity) : severity_(severity), has_logged_(false) {} + + virtual ~CerrLog() { + if (has_logged_) { + std::cerr << std::endl; + } + if (severity_ == RAY_FATAL) { + PrintBackTrace(); + std::abort(); + } + } + + std::ostream &Stream() { + has_logged_ = true; + return std::cerr; + } + + template + CerrLog &operator<<(const T &t) { + if (severity_ != RAY_DEBUG) { + has_logged_ = true; + std::cerr << t; + } + return *this; + } + + protected: + const int severity_; + bool has_logged_; + + void PrintBackTrace() { +#if defined(_EXECINFO_H) || !defined(_WIN32) + void *buffer[255]; + const int calls = backtrace(buffer, sizeof(buffer) / sizeof(void *)); + backtrace_symbols_fd(buffer, calls, 1); +#endif + } +}; + +int RayLog::severity_threshold_ = RAY_INFO; + +#ifdef RAY_USE_GLOG +using namespace google; + +// Glog's severity map. +static int GetMappedSeverity(int severity) { + switch (severity) { + case RAY_DEBUG: + return GLOG_INFO; + case RAY_INFO: + return GLOG_INFO; + case RAY_WARNING: + return GLOG_WARNING; + case RAY_ERROR: + return GLOG_ERROR; + case RAY_FATAL: + return GLOG_FATAL; + default: + RAY_LOG(FATAL) << "Unsupported logging level: " << severity; + // This return won't be hit but compiler needs it. + return GLOG_FATAL; + } +} + +#endif + +void RayLog::StartRayLog(const std::string &app_name, int severity_threshold, + const std::string &log_dir) { +#ifdef RAY_USE_GLOG + severity_threshold_ = severity_threshold; + int mapped_severity_threshold = GetMappedSeverity(severity_threshold_); + google::InitGoogleLogging(app_name.c_str()); + google::SetStderrLogging(mapped_severity_threshold); + // Enble log file if log_dir is not empty. + if (!log_dir.empty()) { + auto dir_ends_with_slash = log_dir; + if (log_dir[log_dir.length() - 1] != '/') { + dir_ends_with_slash += "/"; + } + auto app_name_without_path = app_name; + if (app_name.empty()) { + app_name_without_path = "DefaultApp"; + } else { + // Find the app name without the path. + size_t pos = app_name.rfind('/'); + if (pos != app_name.npos && pos + 1 < app_name.length()) { + app_name_without_path = app_name.substr(pos + 1); + } + } + google::SetLogFilenameExtension(app_name_without_path.c_str()); + google::SetLogDestination(mapped_severity_threshold, log_dir.c_str()); + } +#endif +} + +void RayLog::ShutDownRayLog() { +#ifdef RAY_USE_GLOG + google::ShutdownGoogleLogging(); +#endif +} + +RayLog::RayLog(const char *file_name, int line_number, int severity) { +#ifdef RAY_USE_GLOG + // glog does not have DEBUG level, we can handle it here. + if (severity >= severity_threshold_) { + logging_provider_.reset( + new google::LogMessage(file_name, line_number, GetMappedSeverity(severity))); + } +#else + logging_provider_.reset(new CerrLog(severity)); + *logging_provider_ << file_name << ":" << line_number << ": "; +#endif +} + +std::ostream &RayLog::Stream() { +#ifdef RAY_USE_GLOG + return logging_provider_->stream(); +#else + return logging_provider_->Stream(); +#endif +} + +RayLog::~RayLog() { logging_provider_.reset(); } + +} // namespace ray diff --git a/src/ray/util/logging.h b/src/ray/util/logging.h index d44f785d8..3881d2cd7 100644 --- a/src/ray/util/logging.h +++ b/src/ray/util/logging.h @@ -7,16 +7,24 @@ #include #include +#include #include "ray/util/macros.h" +// Forward declaration for the log provider. +#ifdef RAY_USE_GLOG +namespace google { +class LogMessage; +} // namespace google +typedef google::LogMessage LoggingProvider; +#else namespace ray { +class CerrLog; +} // namespace ray +typedef ray::CerrLog LoggingProvider; +#endif -// Stubbed versions of macros defined in glog/logging.h, intended for -// environments where glog headers aren't available. -// -// Add more as needed. - +namespace ray { // Log levels. LOG ignores them, so their values are abitrary. #define RAY_DEBUG (-1) @@ -25,22 +33,21 @@ namespace ray { #define RAY_ERROR 2 #define RAY_FATAL 3 -#define RAY_LOG_INTERNAL(level) \ - ::ray::internal::CerrLog(level) << __FILE__ << ":" << __LINE__ << ": " +#define RAY_LOG_INTERNAL(level) ::ray::RayLog(__FILE__, __LINE__, level) #define RAY_LOG(level) RAY_LOG_INTERNAL(RAY_##level) -#define RAY_IGNORE_EXPR(expr) ((void) (expr)); +#define RAY_IGNORE_EXPR(expr) ((void)(expr)) -#define RAY_CHECK(condition) \ - (condition) ? 0 : ::ray::internal::FatalLog(RAY_FATAL) \ - << __FILE__ << ":" << __LINE__ \ - << " Check failed: " #condition " " +#define RAY_CHECK(condition) \ + (condition) ? RAY_IGNORE_EXPR(0) : ::ray::Voidify() & \ + ::ray::RayLog(__FILE__, __LINE__, RAY_FATAL) \ + << " Check failed: " #condition " " #ifdef NDEBUG #define RAY_DCHECK(condition) \ - RAY_IGNORE_EXPR(condition) \ - while (false) ::ray::internal::NullLog() + RAY_IGNORE_EXPR(condition); \ + while (false) ::ray::RayLogBase() #else @@ -48,74 +55,62 @@ namespace ray { #endif // NDEBUG -namespace internal { +// To make the logging lib plugable with other logging libs and make +// the implementation unawared by the user, RayLog is only a declaration +// which hide the implementation into logging.cc file. +// In logging.cc, we can choose different log libs using different macros. -class NullLog { +// This is also a null log which does not output anything. +class RayLogBase { public: - template - NullLog &operator<<(const T &t) { + virtual ~RayLogBase(){}; + + template + RayLogBase &operator<<(const T &t) { RAY_IGNORE_EXPR(t); return *this; } }; -class CerrLog { +class RayLog : public RayLogBase { public: - CerrLog(int severity) // NOLINT(runtime/explicit) - : severity_(severity), - has_logged_(false) {} + RayLog(const char *file_name, int line_number, int severity); + virtual ~RayLog(); - virtual ~CerrLog() { - if (has_logged_) { - std::cerr << std::endl; - } - // This code is duplicated in the FatalLog class. - if (severity_ == RAY_FATAL) { -#if defined(_EXECINFO_H) || !defined(_WIN32) - void *buffer[255]; - const int calls = backtrace(buffer, sizeof(buffer) / sizeof(void *)); - backtrace_symbols_fd(buffer, calls, 1); -#endif - std::abort(); - } - } - - template - CerrLog &operator<<(const T &t) { - if (severity_ != RAY_DEBUG) { - has_logged_ = true; - std::cerr << t; + template + RayLogBase &operator<<(const T &t) { + if (logging_provider_ == nullptr) { + // This means the logging level is lower than the threshold. + RAY_IGNORE_EXPR(t); + } else { + this->Stream() << t; } return *this; } - protected: - const int severity_; - bool has_logged_; + // The init function of ray log for a program which should be called only once. + // If logDir is empty, the log won't output to file. + static void StartRayLog(const std::string &appName, int severity_threshold = RAY_ERROR, + const std::string &logDir = ""); + // The shutdown function of ray log which should be used with StartRayLog as a pair. + static void ShutDownRayLog(); + + private: + std::ostream &Stream(); + std::unique_ptr logging_provider_; + static int severity_threshold_; }; -// Clang-tidy isn't smart enough to determine that DCHECK using CerrLog doesn't -// return so we create a new class to give it a hint. -class FatalLog : public CerrLog { +// This class make RAY_CHECK compilation pass to change the << operator to void. +// This class is copied from glog. +class Voidify { public: - explicit FatalLog(int /* severity */) // NOLINT - : CerrLog(RAY_FATAL) {} // NOLINT - - RAY_NORETURN ~FatalLog() { - if (has_logged_) { - std::cerr << std::endl; -#if defined(_EXECINFO_H) || !defined(_WIN32) - void *buffer[255]; - const int calls = backtrace(buffer, sizeof(buffer) / sizeof(void *)); - backtrace_symbols_fd(buffer, calls, 1); -#endif - } - std::abort(); - } + Voidify() {} + // This has to be an operator with a precedence lower than << but + // higher than ?: + void operator&(RayLogBase &) {} }; -} // namespace internal - } // namespace ray #endif // RAY_UTIL_LOGGING_H diff --git a/src/ray/util/logging_test.cc b/src/ray/util/logging_test.cc new file mode 100644 index 000000000..d48c4b6cb --- /dev/null +++ b/src/ray/util/logging_test.cc @@ -0,0 +1,79 @@ +#include +#include +#include + +#include "gtest/gtest.h" +#include "ray/util/logging.h" + +namespace ray { + +int64_t current_time_ms() { + std::chrono::milliseconds ms_since_epoch = + std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()); + return ms_since_epoch.count(); +} + +// This is not really test. +// This file just print some information using the logging macro. + +void PrintLog() { + RAY_LOG(DEBUG) << "This is the DEBUG message"; + RAY_LOG(INFO) << "This is the INFO message"; + RAY_LOG(WARNING) << "This is the WARNING message"; + RAY_LOG(ERROR) << "This is the ERROR message"; + RAY_CHECK(true) << "This is a RAY_CHECK message but it won't show up"; + // The following 2 lines should not run since it will cause program failure. + // RAY_LOG(FATAL) << "This is the FATAL message"; + // RAY_CHECK(false) << "This is a RAY_CHECK message but it won't show up"; +} + +TEST(PrintLogTest, LogTestWithoutInit) { + // Without RayLog::StartRayLog, this should also work. + PrintLog(); +} + +TEST(PrintLogTest, LogTestWithInit) { + // Test empty app name. + RayLog::StartRayLog("", RAY_DEBUG); + PrintLog(); + RayLog::ShutDownRayLog(); +} + +// This test will output large amount of logs to stderr, should be disabled in travis. +TEST(LogPerfTest, PerfTest) { + RayLog::StartRayLog("/fake/path/to/appdire/LogPerfTest", RAY_ERROR, "/tmp/"); + int rounds = 100000; + + int64_t start_time = current_time_ms(); + for (int i = 0; i < rounds; ++i) { + RAY_LOG(DEBUG) << "This is the RAY_DEBUG message"; + } + int64_t elapsed = current_time_ms() - start_time; + std::cout << "Testing DEBUG log for " << rounds << " rounds takes " << elapsed << " ms." + << std::endl; + + start_time = current_time_ms(); + for (int i = 0; i < rounds; ++i) { + RAY_LOG(ERROR) << "This is the RAY_ERROR message"; + } + elapsed = current_time_ms() - start_time; + std::cout << "Testing RAY_ERROR log for " << rounds << " rounds takes " << elapsed + << " ms." << std::endl; + + start_time = current_time_ms(); + for (int i = 0; i < rounds; ++i) { + RAY_CHECK(i >= 0) << "This is a RAY_CHECK message but it won't show up"; + } + elapsed = current_time_ms() - start_time; + std::cout << "Testing RAY_CHECK(true) for " << rounds << " rounds takes " << elapsed + << " ms." << std::endl; + RayLog::ShutDownRayLog(); +} + +} // namespace ray + +int main(int argc, char **argv) { + ::testing::InitGoogleTest(&argc, argv); + return RUN_ALL_TESTS(); +}