From 93e9d2b82cd3560a0049da1d8716e6681f47c60b Mon Sep 17 00:00:00 2001 From: Yuhong Guo Date: Wed, 2 Jan 2019 13:45:29 +0800 Subject: [PATCH] Improve backend log: env variable setting and format refine. (#3662) * Improve backend logging * Address comment * Fix Raul's comment --- src/ray/id.cc | 6 ++++- src/ray/raylet/node_manager.cc | 28 +++++++++++++----------- src/ray/raylet/task_spec.cc | 17 +++++++++++++++ src/ray/raylet/task_spec.h | 2 ++ src/ray/util/logging.cc | 40 ++++++++++++++++++++++++++++++++++ src/ray/util/logging.h | 3 +++ 6 files changed, 82 insertions(+), 14 deletions(-) diff --git a/src/ray/id.cc b/src/ray/id.cc index b3b2b187e..70454bbdf 100644 --- a/src/ray/id.cc +++ b/src/ray/id.cc @@ -155,7 +155,11 @@ uint64_t MurmurHash64A(const void *key, int len, unsigned int seed) { size_t UniqueID::hash() const { return MurmurHash64A(&id_[0], kUniqueIDSize, 0); } std::ostream &operator<<(std::ostream &os, const UniqueID &id) { - os << id.hex(); + if (id.is_nil()) { + os << "NIL_ID"; + } else { + os << id.hex(); + } return os; } diff --git a/src/ray/raylet/node_manager.cc b/src/ray/raylet/node_manager.cc index fd7013248..b14479084 100644 --- a/src/ray/raylet/node_manager.cc +++ b/src/ray/raylet/node_manager.cc @@ -512,7 +512,7 @@ void NodeManager::HandleActorStateTransition(const ActorID &actor_id, ActorRegistration actor_registration(data); RAY_LOG(DEBUG) << "Actor notification received: actor_id = " << actor_id << ", node_manager_id = " << actor_registration.GetNodeManagerId() - << ", state = " << static_cast(actor_registration.GetState()) + << ", state = " << EnumNameActorState(actor_registration.GetState()) << ", remaining_reconstructions = " << actor_registration.GetRemainingReconstructions(); // Update local registry. @@ -639,10 +639,10 @@ void NodeManager::DispatchTasks( void NodeManager::ProcessClientMessage( const std::shared_ptr &client, int64_t message_type, const uint8_t *message_data) { - RAY_LOG(DEBUG) << "Message of type " << message_type; - auto registered_worker = worker_pool_.GetRegisteredWorker(client); auto message_type_value = static_cast(message_type); + RAY_LOG(DEBUG) << "Message of " << protocol::EnumNameMessageType(message_type_value) + << "(" << message_type << ")"; if (registered_worker && registered_worker->IsDead()) { // For a worker that is marked as dead (because the driver has died already), // all the messages are ignored except DisconnectClient. @@ -1212,9 +1212,12 @@ void NodeManager::SubmitTask(const Task &task, const Lineage &uncommitted_lineag bool forwarded) { const TaskSpecification &spec = task.GetTaskSpecification(); const TaskID &task_id = spec.TaskId(); - RAY_LOG(DEBUG) << "Submitting task: task_id = " << task_id - << ", actor_id = " << spec.ActorId() - << ", actor_creation_id = " << spec.ActorCreationId(); + RAY_LOG(DEBUG) << "Submitting task: task_id=" << task_id + << ", actor_id=" << spec.ActorId() + << ", actor_creation_id=" << spec.ActorCreationId() + << ", actor_handle_id=" << spec.ActorHandleId() + << ", actor_counter=" << spec.ActorCounter() + << ", task_descriptor=" << spec.FunctionDescriptorString(); if (local_queues_.HasTask(task_id)) { RAY_LOG(WARNING) << "Submitted task " << task_id @@ -1474,7 +1477,8 @@ bool NodeManager::AssignTask(const Task &task) { return false; } - RAY_LOG(DEBUG) << "Assigning task to worker with pid " << worker->Pid(); + RAY_LOG(DEBUG) << "Assigning task " << spec.TaskId() << " to worker with pid " + << worker->Pid(); flatbuffers::FlatBufferBuilder fbb; // Resource accounting: acquire resources for the assigned task. @@ -1531,9 +1535,8 @@ bool NodeManager::AssignTask(const Task &task) { } // We started running the task, so the task is ready to write to GCS. if (!lineage_cache_.AddReadyTask(assigned_task)) { - RAY_LOG(WARNING) << "Task " << spec.TaskId() << " already in lineage cache. " - "This is most likely due to " - "reconstruction."; + RAY_LOG(WARNING) << "Task " << spec.TaskId() << " already in lineage cache." + << " This is most likely due to reconstruction."; } // Mark the task as running. // (See design_docs/task_states.rst for the state transition diagram.) @@ -1869,9 +1872,8 @@ void NodeManager::ForwardTask(const Task &task, const ClientID &node_id, // lineage cache since the receiving node is now responsible for writing // the task to the GCS. if (!lineage_cache_.RemoveWaitingTask(task_id)) { - RAY_LOG(WARNING) << "Task " << task_id << " already removed from the lineage " - "cache. This is most likely due to " - "reconstruction."; + RAY_LOG(WARNING) << "Task " << task_id << " already removed from the lineage" + << " cache. This is most likely due to reconstruction."; } // Mark as forwarded so that the task and its lineage is not re-forwarded // in the future to the receiving node. diff --git a/src/ray/raylet/task_spec.cc b/src/ray/raylet/task_spec.cc index 7e33a9acf..f4b0b32fc 100644 --- a/src/ray/raylet/task_spec.cc +++ b/src/ray/raylet/task_spec.cc @@ -1,5 +1,7 @@ #include "task_spec.h" +#include + #include "ray/common/common_protocol.h" #include "ray/gcs/format/gcs_generated.h" #include "ray/util/logging.h" @@ -139,6 +141,21 @@ std::vector TaskSpecification::FunctionDescriptor() const { return string_vec_from_flatbuf(*message->function_descriptor()); } +std::string TaskSpecification::FunctionDescriptorString() const { + auto message = flatbuffers::GetRoot(spec_.data()); + auto list = string_vec_from_flatbuf(*message->function_descriptor()); + std::ostringstream stream; + // The 4th is the code hash which is binary bits. No need to output it. + int size = std::min(static_cast(3), list.size()); + for (int i = 0; i < size; ++i) { + if (i != 0) { + stream << ","; + } + stream << list[i]; + } + return stream.str(); +} + int64_t TaskSpecification::NumArgs() const { auto message = flatbuffers::GetRoot(spec_.data()); return message->args()->size(); diff --git a/src/ray/raylet/task_spec.h b/src/ray/raylet/task_spec.h index da33275e9..e517af71c 100644 --- a/src/ray/raylet/task_spec.h +++ b/src/ray/raylet/task_spec.h @@ -160,6 +160,8 @@ class TaskSpecification { TaskID ParentTaskId() const; int64_t ParentCounter() const; std::vector FunctionDescriptor() const; + // Output the function descriptor as a string for log purpose. + std::string FunctionDescriptorString() const; int64_t NumArgs() const; int64_t NumReturns() const; bool ArgByRef(int64_t arg_index) const; diff --git a/src/ray/util/logging.cc b/src/ray/util/logging.cc index b10c245e7..cdc12e427 100644 --- a/src/ray/util/logging.cc +++ b/src/ray/util/logging.cc @@ -3,7 +3,10 @@ #ifndef _WIN32 #include #endif + +#include #include +#include #include #include @@ -92,6 +95,26 @@ static int GetMappedSeverity(RayLogLevel severity) { void RayLog::StartRayLog(const std::string &app_name, RayLogLevel severity_threshold, const std::string &log_dir) { + const char *var_value = getenv("RAY_BACKEND_LOG_LEVEL"); + if (var_value != nullptr) { + std::string data = var_value; + std::transform(data.begin(), data.end(), data.begin(), ::tolower); + if (data == "debug") { + severity_threshold = RayLogLevel::DEBUG; + } else if (data == "info") { + severity_threshold = RayLogLevel::INFO; + } else if (data == "warning") { + severity_threshold = RayLogLevel::WARNING; + } else if (data == "error") { + severity_threshold = RayLogLevel::ERROR; + } else if (data == "fatal") { + severity_threshold = RayLogLevel::FATAL; + } else { + RAY_LOG(WARNING) << "Unrecognized setting of RAY_BACKEND_LOG_LEVEL=" << var_value; + } + RAY_LOG(INFO) << "Set ray log level from environment variable RAY_BACKEND_LOG_LEVEL" + << " to " << static_cast(severity_threshold); + } severity_threshold_ = severity_threshold; app_name_ = app_name; #ifdef RAY_USE_GLOG @@ -120,8 +143,25 @@ void RayLog::StartRayLog(const std::string &app_name, RayLogLevel severity_thres #endif } +void RayLog::UninstallSignalAction() { +#ifdef RAY_USE_GLOG + RAY_LOG(DEBUG) << "Uninstall signal handlers."; + // This signal list comes from glog's signalhandler.cc. + // https://github.com/google/glog/blob/master/src/signalhandler.cc#L58-L70 + static std::vector installed_signals({SIGSEGV, SIGILL, SIGFPE, SIGABRT, SIGTERM}); + struct sigaction sig_action; + memset(&sig_action, 0, sizeof(sig_action)); + sigemptyset(&sig_action.sa_mask); + sig_action.sa_handler = SIG_DFL; + for (int signal_num : installed_signals) { + sigaction(signal_num, &sig_action, NULL); + } +#endif +} + void RayLog::ShutDownRayLog() { #ifdef RAY_USE_GLOG + UninstallSignalAction(); google::ShutdownGoogleLogging(); #endif } diff --git a/src/ray/util/logging.h b/src/ray/util/logging.h index 00c934c68..1da3652a7 100644 --- a/src/ray/util/logging.h +++ b/src/ray/util/logging.h @@ -82,6 +82,9 @@ class RayLog : public RayLogBase { /// The shutdown function of ray log which should be used with StartRayLog as a pair. static void ShutDownRayLog(); + /// Uninstall the signal actions installed by InstallFailureSignalHandler. + static void UninstallSignalAction(); + /// Return whether or not the log level is enabled in current setting. /// /// \param log_level The input log level to test.