diff --git a/dbms/src/Flash/Mpp/MPPHandler.cpp b/dbms/src/Flash/Mpp/MPPHandler.cpp index 932c3e81558..de7feba9823 100644 --- a/dbms/src/Flash/Mpp/MPPHandler.cpp +++ b/dbms/src/Flash/Mpp/MPPHandler.cpp @@ -106,7 +106,7 @@ grpc::Status MPPHandler::execute(const ContextPtr & context, mpp::DispatchTaskRe #endif task->run(); - LOG_INFO(log, "processing dispatch is over; the time cost is {} ms", stopwatch.elapsedMilliseconds()); + LOG_DEBUG(log, "processing dispatch is over; the time cost is {} ms", stopwatch.elapsedMilliseconds()); } catch (Exception & e) { diff --git a/dbms/src/Flash/Mpp/MPPTask.cpp b/dbms/src/Flash/Mpp/MPPTask.cpp index 1b1fe18549a..3dd22f7a8a3 100644 --- a/dbms/src/Flash/Mpp/MPPTask.cpp +++ b/dbms/src/Flash/Mpp/MPPTask.cpp @@ -155,7 +155,7 @@ MPPTask::~MPPTask() if (query_memory_tracker != nullptr && current_memory_tracker != query_memory_tracker) current_memory_tracker = query_memory_tracker; abortTunnels("", true); - LOG_INFO(log, "finish MPPTask: {}, total run time is {} ms", id.toString(), total_run_time_ms); + LOG_DEBUG(log, "finish MPPTask: {}", id.toString()); } bool MPPTask::isRootMPPTask() const @@ -452,11 +452,16 @@ void MPPTask::unregisterTask() { if (is_registered) { + Stopwatch watch; auto [result, reason] = manager->unregisterTask(id, getErrString()); + auto elapsed_ms = watch.elapsedMilliseconds(); if (result) - LOG_DEBUG(log, "task unregistered"); + { + auto log_level = elapsed_ms > 1000 ? Poco::Message::PRIO_INFORMATION : Poco::Message::PRIO_DEBUG; + LOG_IMPL(log, log_level, "task unregistered, time cost is {} ms", elapsed_ms); + } else - LOG_WARNING(log, "task failed to unregister, reason: {}", reason); + LOG_WARNING(log, "task failed to unregister, time cost is {} ms, reason: {}", elapsed_ms, reason); } } @@ -643,8 +648,12 @@ void MPPTask::runImpl() auto time_cost_in_schedule_ns = stopwatch.elapsed() - time_cost_in_preprocess_ns; dag_context->minTSO_wait_time_ns = time_cost_in_schedule_ns; auto time_cost_in_schedule_ms = time_cost_in_schedule_ns / MILLISECOND_TO_NANO; - LOG_INFO( + auto time_cost_before_running_ms = time_cost_in_schedule_ms + time_cost_in_preprocess_ms; + auto log_level + = time_cost_before_running_ms > 1000 ? Poco::Message::PRIO_INFORMATION : Poco::Message::PRIO_DEBUG; + LOG_IMPL( log, + log_level, "task starts running, time cost in schedule: {} ms, time cost in preprocess: {} ms", time_cost_in_schedule_ms, time_cost_in_preprocess_ms); @@ -671,7 +680,7 @@ void MPPTask::runImpl() auto result = query_executor_holder->execute(); - auto log_level = Poco::Message::PRIO_DEBUG; + log_level = Poco::Message::PRIO_DEBUG; if (!result.is_success || status != RUNNING) log_level = Poco::Message::PRIO_INFORMATION; LOG_IMPL( @@ -778,6 +787,7 @@ void MPPTask::runImpl() total_run_time_ms = stopwatch.elapsedMilliseconds(); LOG_DEBUG(log, "task ends, time cost is {} ms.", total_run_time_ms); + unregisterTask(); } diff --git a/dbms/src/Flash/Pipeline/Schedule/Events/Event.cpp b/dbms/src/Flash/Pipeline/Schedule/Events/Event.cpp index e6a68af0965..de398ae0f91 100644 --- a/dbms/src/Flash/Pipeline/Schedule/Events/Event.cpp +++ b/dbms/src/Flash/Pipeline/Schedule/Events/Event.cpp @@ -81,7 +81,7 @@ void Event::onInputFinish() if (0 == cur_value) { schedule(); - LOG_INFO(log, "Event is scheduled"); + LOG_DEBUG(log, "Event is scheduled"); } }