From 0a6164ab150e66c2159e1d4342b1965cd0096559 Mon Sep 17 00:00:00 2001 From: SangBin Cho Date: Mon, 28 Sep 2020 21:07:45 -0700 Subject: [PATCH] [Core] Improve logging messages. (#11082) --- src/ray/core_worker/profiling.cc | 4 +++- src/ray/gcs/gcs_server/gcs_actor_manager.cc | 22 +++++++++---------- src/ray/gcs/gcs_server/gcs_node_manager.cc | 3 ++- .../gcs_server/gcs_placement_group_manager.cc | 14 ++++++------ .../gcs_placement_group_scheduler.cc | 19 ++++++++-------- src/ray/gcs/gcs_server/gcs_worker_manager.cc | 4 +++- src/ray/object_manager/object_manager.cc | 2 +- src/ray/raylet/node_manager.cc | 14 ++++++++---- src/ray/stats/metric_exporter.cc | 4 +++- 9 files changed, 48 insertions(+), 38 deletions(-) diff --git a/src/ray/core_worker/profiling.cc b/src/ray/core_worker/profiling.cc index 1353715cb..7d4373c8b 100644 --- a/src/ray/core_worker/profiling.cc +++ b/src/ray/core_worker/profiling.cc @@ -59,7 +59,9 @@ void Profiler::FlushEvents() { if (cur_profile_data->profile_events_size() != 0) { if (!gcs_client_->Stats().AsyncAddProfileData(cur_profile_data, nullptr).ok()) { - RAY_LOG(WARNING) << "Failed to push profile events to GCS."; + RAY_LOG(WARNING) + << "Failed to push profile events to GCS. This won't affect core Ray, but you " + "might lose profile data, and ray timeline might not work as expected."; } else { RAY_LOG(DEBUG) << "Pushed " << cur_profile_data->profile_events_size() << " events to GCS."; diff --git a/src/ray/gcs/gcs_server/gcs_actor_manager.cc b/src/ray/gcs/gcs_server/gcs_actor_manager.cc index b63c145a3..5ef74d0c7 100644 --- a/src/ray/gcs/gcs_server/gcs_actor_manager.cc +++ b/src/ray/gcs/gcs_server/gcs_actor_manager.cc @@ -481,7 +481,7 @@ Status GcsActorManager::CreateActor(const ray::rpc::CreateActorRequest &request, auto iter = registered_actors_.find(actor_id); if (iter == registered_actors_.end()) { - RAY_LOG(WARNING) << "Actor " << actor_id << " may be already destroyed."; + RAY_LOG(INFO) << "Actor " << actor_id << " may be already destroyed."; return Status::Invalid("Actor may be already destroyed."); } @@ -558,10 +558,10 @@ void GcsActorManager::PollOwnerForActorOutOfScope( wait_request, [this, owner_node_id, owner_id, actor_id]( Status status, const rpc::WaitForActorOutOfScopeReply &reply) { if (!status.ok()) { - RAY_LOG(WARNING) << "Worker " << owner_id << " failed, destroying actor child."; + RAY_LOG(INFO) << "Worker " << owner_id << " failed, destroying actor child."; } else { - RAY_LOG(WARNING) << "Actor " << actor_id - << " is out of scope,, destroying actor child."; + RAY_LOG(INFO) << "Actor " << actor_id + << " is out of scope,, destroying actor child."; } auto node_it = owners_.find(owner_node_id); @@ -699,8 +699,8 @@ void GcsActorManager::OnWorkerDead(const ray::NodeID &node_id, RAY_LOG(INFO) << "Worker " << worker_id << " on node " << node_id << " intentional exit."; } else { - RAY_LOG(WARNING) << "Worker " << worker_id << " on node " << node_id - << " failed and exited abnormally."; + RAY_LOG(INFO) << "Worker " << worker_id << " on node " << node_id + << " failed and exited abnormally."; } // Destroy all actors that are owned by this worker. const auto it = owners_.find(node_id); @@ -747,7 +747,7 @@ void GcsActorManager::OnWorkerDead(const ray::NodeID &node_id, } void GcsActorManager::OnNodeDead(const NodeID &node_id) { - RAY_LOG(WARNING) << "Node " << node_id << " failed, reconstructing actors."; + RAY_LOG(INFO) << "Node " << node_id << " failed, reconstructing actors."; const auto it = owners_.find(node_id); if (it != owners_.end()) { std::vector children_ids; @@ -816,9 +816,9 @@ void GcsActorManager::ReconstructActor(const ActorID &actor_id, bool need_resche int64_t remaining = max_restarts - num_restarts; remaining_restarts = std::max(remaining, static_cast(0)); } - RAY_LOG(WARNING) << "Actor is failed " << actor_id << " on worker " << worker_id - << " at node " << node_id << ", need_reschedule = " << need_reschedule - << ", remaining_restarts = " << remaining_restarts; + RAY_LOG(INFO) << "Actor is failed " << actor_id << " on worker " << worker_id + << " at node " << node_id << ", need_reschedule = " << need_reschedule + << ", remaining_restarts = " << remaining_restarts; if (remaining_restarts != 0) { // num_restarts must be set before updating GCS, or num_restarts will be inconsistent // between memory cache and storage. @@ -881,8 +881,6 @@ void GcsActorManager::OnActorCreationSuccess(const std::shared_ptr &ac // and GCS server will destroy the actor. The actor creation is asynchronous, it may be // destroyed before the actor creation is completed. if (registered_actors_.count(actor_id) == 0) { - RAY_LOG(WARNING) << "Actor is destroyed before the creation is completed, actor id = " - << actor_id; return; } actor->UpdateState(rpc::ActorTableData::ALIVE); diff --git a/src/ray/gcs/gcs_server/gcs_node_manager.cc b/src/ray/gcs/gcs_server/gcs_node_manager.cc index fbcaee68b..1166a8eca 100644 --- a/src/ray/gcs/gcs_server/gcs_node_manager.cc +++ b/src/ray/gcs/gcs_server/gcs_node_manager.cc @@ -405,7 +405,8 @@ std::shared_ptr GcsNodeManager::RemoveNode( std::ostringstream error_message; error_message << "The node with node id " << node_id << " has been marked dead because the detector" - << " has missed too many heartbeats from it."; + << " has missed too many heartbeats from it. This can happen when a " + "raylet crashes unexpectedly or has lagging heartbeats."; auto error_data_ptr = gcs::CreateErrorTableData(type, error_message.str(), current_time_ms()); RAY_CHECK_OK(gcs_pub_sub_->Publish(ERROR_INFO_CHANNEL, node_id.Hex(), diff --git a/src/ray/gcs/gcs_server/gcs_placement_group_manager.cc b/src/ray/gcs/gcs_server/gcs_placement_group_manager.cc index 846ed9cc1..a6b83b419 100644 --- a/src/ray/gcs/gcs_server/gcs_placement_group_manager.cc +++ b/src/ray/gcs/gcs_server/gcs_placement_group_manager.cc @@ -120,8 +120,8 @@ PlacementGroupID GcsPlacementGroupManager::GetPlacementGroupIDByName( void GcsPlacementGroupManager::OnPlacementGroupCreationFailed( std::shared_ptr placement_group) { - RAY_LOG(WARNING) << "Failed to create placement group " << placement_group->GetName() - << ", try again."; + RAY_LOG(INFO) << "Failed to create placement group " << placement_group->GetName() + << ", try again."; // We will attempt to schedule this placement_group once an eligible node is // registered. auto state = placement_group->GetState(); @@ -219,9 +219,9 @@ void GcsPlacementGroupManager::HandleCreatePlacementGroup( RAY_LOG(INFO) << "Finished registering placement group, " << placement_group->DebugString(); } else { - RAY_LOG(WARNING) << "Failed to register placement group, " - << placement_group->DebugString() - << ", cause: " << status.message(); + RAY_LOG(INFO) << "Failed to register placement group, " + << placement_group->DebugString() + << ", cause: " << status.message(); } GCS_RPC_SEND_REPLY(send_reply_callback, reply, status); }); @@ -327,8 +327,8 @@ void GcsPlacementGroupManager::RetryCreatingPlacementGroup() { } void GcsPlacementGroupManager::OnNodeDead(const NodeID &node_id) { - RAY_LOG(WARNING) << "Node " << node_id - << " failed, rescheduling the placement groups on the dead node."; + RAY_LOG(INFO) << "Node " << node_id + << " failed, rescheduling the placement groups on the dead node."; auto bundles = gcs_placement_group_scheduler_->GetBundlesOnNode(node_id); for (const auto &bundle : bundles) { auto iter = registered_placement_groups_.find(bundle.first); diff --git a/src/ray/gcs/gcs_server/gcs_placement_group_scheduler.cc b/src/ray/gcs/gcs_server/gcs_placement_group_scheduler.cc index 1cc7abfb2..eb45b64b7 100644 --- a/src/ray/gcs/gcs_server/gcs_placement_group_scheduler.cc +++ b/src/ray/gcs/gcs_server/gcs_placement_group_scheduler.cc @@ -208,8 +208,8 @@ void GcsPlacementGroupScheduler::ScheduleUnplacedBundles( // If no nodes are available, scheduling fails. if (selected_nodes.empty()) { - RAY_LOG(WARNING) << "Failed to schedule placement group " - << placement_group->GetName() << ", because no nodes are available."; + RAY_LOG(INFO) << "Failed to schedule placement group " << placement_group->GetName() + << ", because no nodes are available."; failure_callback(placement_group); return; } @@ -299,8 +299,8 @@ void GcsPlacementGroupScheduler::PrepareResources( RAY_LOG(INFO) << "Finished leasing resource from " << node_id << " for bundle: " << bundle->DebugString(); } else { - RAY_LOG(WARNING) << "Failed to lease resource from " << node_id - << " for bundle: " << bundle->DebugString(); + RAY_LOG(INFO) << "Failed to lease resource from " << node_id + << " for bundle: " << bundle->DebugString(); } callback(result); }); @@ -321,8 +321,8 @@ void GcsPlacementGroupScheduler::CommitResources( RAY_LOG(INFO) << "Finished committing resource to " << node_id << " for bundle: " << bundle->DebugString(); } else { - RAY_LOG(WARNING) << "Failed to commit resource to " << node_id - << " for bundle: " << bundle->DebugString(); + RAY_LOG(INFO) << "Failed to commit resource to " << node_id + << " for bundle: " << bundle->DebugString(); } RAY_CHECK(callback); callback(status); @@ -333,10 +333,9 @@ void GcsPlacementGroupScheduler::CancelResourceReserve( const std::shared_ptr &bundle_spec, const std::shared_ptr &node) { if (node == nullptr) { - RAY_LOG(WARNING) << "Node for a placement group id " - << bundle_spec->PlacementGroupId() << " and a bundle index, " - << bundle_spec->Index() - << " has already removed. Cancellation request will be ignored."; + RAY_LOG(INFO) << "Node for a placement group id " << bundle_spec->PlacementGroupId() + << " and a bundle index, " << bundle_spec->Index() + << " has already removed. Cancellation request will be ignored."; return; } auto node_id = NodeID::FromBinary(node->node_id()); diff --git a/src/ray/gcs/gcs_server/gcs_worker_manager.cc b/src/ray/gcs/gcs_server/gcs_worker_manager.cc index e8d53d858..70bb4a8b4 100644 --- a/src/ray/gcs/gcs_server/gcs_worker_manager.cc +++ b/src/ray/gcs/gcs_server/gcs_worker_manager.cc @@ -30,7 +30,9 @@ void GcsWorkerManager::HandleReportWorkerFailure( if (request.worker_failure().intentional_disconnect()) { RAY_LOG(INFO) << log_stream.str(); } else { - RAY_LOG(WARNING) << log_stream.str(); + RAY_LOG(WARNING) << log_stream.str() + << ". If there are lots of this logs, that might indicate there are " + "unexpected failures in the cluster."; } auto worker_failure_data = std::make_shared(); worker_failure_data->CopyFrom(request.worker_failure()); diff --git a/src/ray/object_manager/object_manager.cc b/src/ray/object_manager/object_manager.cc index ee7d412bd..186b824e8 100644 --- a/src/ray/object_manager/object_manager.cc +++ b/src/ray/object_manager/object_manager.cc @@ -397,7 +397,7 @@ void ObjectManager::Push(const ObjectID &object_id, const NodeID &client_id) { if (config_.push_timeout_ms == 0) { // The Push request fails directly when config_.push_timeout_ms == 0. RAY_LOG(WARNING) << "Invalid Push request ObjectID " << object_id - << " due to direct timeout setting. "; + << " due to direct timeout setting. (0 ms timeout)"; } else if (config_.push_timeout_ms > 0) { // Put the task into a queue and wait for the notification of Object added. timer.reset(new boost::asio::deadline_timer(*main_service_)); diff --git a/src/ray/raylet/node_manager.cc b/src/ray/raylet/node_manager.cc index c7d618408..a14cc873e 100644 --- a/src/ray/raylet/node_manager.cc +++ b/src/ray/raylet/node_manager.cc @@ -380,7 +380,10 @@ void NodeManager::Heartbeat() { uint64_t interval = now_ms - last_heartbeat_at_ms_; if (interval > RayConfig::instance().num_heartbeats_warning() * RayConfig::instance().raylet_heartbeat_timeout_milliseconds()) { - RAY_LOG(WARNING) << "Last heartbeat was sent " << interval << " ms ago "; + RAY_LOG(WARNING) + << "Last heartbeat was sent " << interval + << " ms ago. There might be resource pressure on this node. If heartbeat keeps " + "lagging, this node can be marked as dead mistakenly."; } last_heartbeat_at_ms_ = now_ms; @@ -497,7 +500,8 @@ void NodeManager::DoLocalGC() { for (const auto &driver : worker_pool_.GetAllRegisteredDrivers()) { all_workers.push_back(driver); } - RAY_LOG(WARNING) << "Sending local GC request to " << all_workers.size() << " workers."; + RAY_LOG(WARNING) << "Sending local GC request to " << all_workers.size() + << " workers. It is due to memory pressure on the local node."; for (const auto &worker : all_workers) { rpc::LocalGCRequest request; worker->rpc_client()->LocalGC( @@ -536,7 +540,7 @@ void NodeManager::SpillObjects(const std::vector &objects_ids_to_spill // the local worker. if (pinned_objects_.count(id) == 0) { RAY_LOG(WARNING) << "Requested spill for object that has not yet been marked as " - "the primary copy"; + "the primary copy."; } } if (objects_ids.empty()) { @@ -3460,7 +3464,9 @@ void NodeManager::HandleGlobalGC(const rpc::GlobalGCRequest &request, } void NodeManager::TriggerGlobalGC() { - RAY_LOG(WARNING) << "Broadcasting global GC request to all raylets."; + RAY_LOG(WARNING) + << "Broadcasting global GC request to all raylets. This is usually because " + "clusters have memory pressure, and ray needs to GC unused memory."; should_global_gc_ = true; // We won't see our own request, so trigger local GC in the next heartbeat. should_local_gc_ = true; diff --git a/src/ray/stats/metric_exporter.cc b/src/ray/stats/metric_exporter.cc index ec7bf5836..f3de14930 100644 --- a/src/ray/stats/metric_exporter.cc +++ b/src/ray/stats/metric_exporter.cc @@ -208,7 +208,9 @@ void OpenCensusProtoExporter::ExportViewData( request_proto, [](const Status &status, const rpc::ReportOCMetricsReply &reply) { RAY_UNUSED(reply); if (!status.ok()) { - RAY_LOG(WARNING) << "Export metrics to agent failed: " << status; + RAY_LOG(WARNING) + << "Export metrics to agent failed: " << status + << ". This won't affect Ray, but you can lose metrics from the cluster."; } }); }