From 605f5bec809bb07c4b54cfbd0a256d0e252efb5c Mon Sep 17 00:00:00 2001 From: zclllhhjj Date: Tue, 5 Nov 2024 14:18:25 +0800 Subject: [PATCH 1/2] [Enhancement](log) Make query relative BE log more reasonable (#42900) Issue Number: close #xxx before we have many info logs which may not useful when a query runs. now we reduced them. keep one info log for each stage below: 1. query arrive 2. FE tells to run fragment 3. query finished and no others --- be/src/pipeline/exec/result_sink_operator.cpp | 9 +++++---- be/src/pipeline/pipeline_fragment_context.cpp | 3 --- be/src/runtime/fragment_mgr.cpp | 8 +++++--- be/src/runtime/query_context.cpp | 4 +++- 4 files changed, 13 insertions(+), 11 deletions(-) diff --git a/be/src/pipeline/exec/result_sink_operator.cpp b/be/src/pipeline/exec/result_sink_operator.cpp index 52daf425f5576a..b1cd3e27a7eca1 100644 --- a/be/src/pipeline/exec/result_sink_operator.cpp +++ b/be/src/pipeline/exec/result_sink_operator.cpp @@ -18,11 +18,11 @@ #include "result_sink_operator.h" #include +#include #include #include "common/config.h" -#include "common/object_pool.h" #include "exec/rowid_fetcher.h" #include "pipeline/exec/operator.h" #include "runtime/buffer_control_block.h" @@ -202,9 +202,10 @@ Status ResultSinkLocalState::close(RuntimeState* state, Status exec_status) { final_status = st; } - LOG_INFO("Query {} result sink closed with status {} and has written {} rows", - print_id(state->query_id()), final_status.to_string_no_stack(), - _writer->get_written_rows()); + VLOG_NOTICE << fmt::format( + "Query {} result sink closed with status {} and has written {} rows", + print_id(state->query_id()), final_status.to_string_no_stack(), + _writer->get_written_rows()); } // close sender, this is normal path end diff --git a/be/src/pipeline/pipeline_fragment_context.cpp b/be/src/pipeline/pipeline_fragment_context.cpp index e514a5d6b975ac..30a7ce07315581 100644 --- a/be/src/pipeline/pipeline_fragment_context.cpp +++ b/be/src/pipeline/pipeline_fragment_context.cpp @@ -250,9 +250,6 @@ Status PipelineFragmentContext::prepare(const doris::TPipelineFragmentParams& re auto* fragment_context = this; - LOG_INFO("Preparing instance {}|{}, backend_num {}", print_id(_query_id), - print_id(local_params.fragment_instance_id), local_params.backend_num); - // 1. init _runtime_state _runtime_state = RuntimeState::create_unique( local_params.fragment_instance_id, request.query_id, request.fragment_id, diff --git a/be/src/runtime/fragment_mgr.cpp b/be/src/runtime/fragment_mgr.cpp index cd8eabb06424c3..3a4c752ccaecdc 100644 --- a/be/src/runtime/fragment_mgr.cpp +++ b/be/src/runtime/fragment_mgr.cpp @@ -698,12 +698,13 @@ Status FragmentMgr::exec_plan_fragment(const TPipelineFragmentParams& params, } Status FragmentMgr::start_query_execution(const PExecPlanFragmentStartRequest* request) { + TUniqueId query_id; + query_id.__set_hi(request->query_id().hi()); + query_id.__set_lo(request->query_id().lo()); std::shared_ptr q_ctx = nullptr; { std::lock_guard lock(_lock); - TUniqueId query_id; - query_id.__set_hi(request->query_id().hi()); - query_id.__set_lo(request->query_id().lo()); + auto search = _query_ctx_map.find(query_id); if (search == _query_ctx_map.end()) { return Status::InternalError( @@ -714,6 +715,7 @@ Status FragmentMgr::start_query_execution(const PExecPlanFragmentStartRequest* r q_ctx = search->second; } q_ctx->set_ready_to_execute(false); + LOG_INFO("Query {} start execution", print_id(query_id)); return Status::OK(); } diff --git a/be/src/runtime/query_context.cpp b/be/src/runtime/query_context.cpp index fa4321ad6c4d12..708fd4b2fc365e 100644 --- a/be/src/runtime/query_context.cpp +++ b/be/src/runtime/query_context.cpp @@ -20,6 +20,7 @@ #include #include +#include "common/logging.h" #include "pipeline/pipeline_fragment_context.h" #include "pipeline/pipeline_x/dependency.h" #include "runtime/runtime_query_statistics_mgr.h" @@ -185,7 +186,8 @@ QueryContext::~QueryContext() { _exec_env->spill_stream_mgr()->async_cleanup_query(_query_id); DorisMetrics::instance()->query_ctx_cnt->increment(-1); - LOG_INFO("Query {} deconstructed, {}", print_id(this->_query_id), mem_tracker_msg); + // the only one msg shows query's end. any other msg should append to it if need. + LOG_INFO("Query {} deconstructed, mem_tracker: {}", print_id(this->_query_id), mem_tracker_msg); } void QueryContext::set_ready_to_execute(bool is_cancelled) { From 4eda048e4393b781cab8f8364471a074bede6c31 Mon Sep 17 00:00:00 2001 From: zclllhhjj Date: Mon, 28 Oct 2024 10:19:09 +0800 Subject: [PATCH 2/2] [chore](log) Reduce some BE execution log (#42383) 1. timeout does not print stack 2. when the runtime filter's relative query is finished before, it does not print the log. --- be/src/common/status.h | 2 +- be/src/pipeline/exec/result_sink_operator.cpp | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/be/src/common/status.h b/be/src/common/status.h index b2754bc3c572e7..74c27024059c43 100644 --- a/be/src/common/status.h +++ b/be/src/common/status.h @@ -470,7 +470,7 @@ class [[nodiscard]] Status { ERROR_CTOR_NOSTACK(Cancelled, CANCELLED) ERROR_CTOR(MemoryLimitExceeded, MEM_LIMIT_EXCEEDED) ERROR_CTOR(RpcError, THRIFT_RPC_ERROR) - ERROR_CTOR(TimedOut, TIMEOUT) + ERROR_CTOR_NOSTACK(TimedOut, TIMEOUT) ERROR_CTOR_NOSTACK(TooManyTasks, TOO_MANY_TASKS) ERROR_CTOR(Uninitialized, UNINITIALIZED) ERROR_CTOR(Aborted, ABORTED) diff --git a/be/src/pipeline/exec/result_sink_operator.cpp b/be/src/pipeline/exec/result_sink_operator.cpp index b1cd3e27a7eca1..8f33aa9bed2f67 100644 --- a/be/src/pipeline/exec/result_sink_operator.cpp +++ b/be/src/pipeline/exec/result_sink_operator.cpp @@ -17,8 +17,8 @@ #include "result_sink_operator.h" -#include #include +#include #include