From 898dd8b23223d46d09118bacca638b06ad093328 Mon Sep 17 00:00:00 2001 From: xufei Date: Mon, 25 Dec 2023 10:48:39 +0800 Subject: [PATCH] add more log Signed-off-by: xufei --- dbms/src/Flash/Coprocessor/DAGStorageInterpreter.cpp | 4 +++- dbms/src/Flash/EstablishCall.cpp | 8 +++++++- dbms/src/Flash/FlashService.cpp | 6 +++--- dbms/src/Flash/Mpp/MPPTask.cpp | 5 ++++- dbms/src/Flash/Mpp/MPPTaskStatistics.cpp | 4 +++- dbms/src/Interpreters/executeQuery.cpp | 2 +- 6 files changed, 21 insertions(+), 8 deletions(-) diff --git a/dbms/src/Flash/Coprocessor/DAGStorageInterpreter.cpp b/dbms/src/Flash/Coprocessor/DAGStorageInterpreter.cpp index a167d28540c..0197d171ffb 100644 --- a/dbms/src/Flash/Coprocessor/DAGStorageInterpreter.cpp +++ b/dbms/src/Flash/Coprocessor/DAGStorageInterpreter.cpp @@ -1003,10 +1003,12 @@ std::unordered_map DAG else /// If first try failed, sync schema and try again. { - LOG_DEBUG(log, "not OK, syncing schemas."); + LOG_INFO(log, "not OK, syncing schemas."); sync_schema(); + LOG_INFO(log, "syncing schemas done."); + std::tie(storages, locks, storage_schema_versions, ok) = get_and_lock_storages(true); if (ok) { diff --git a/dbms/src/Flash/EstablishCall.cpp b/dbms/src/Flash/EstablishCall.cpp index a04e5fae2c3..13c7dbce901 100644 --- a/dbms/src/Flash/EstablishCall.cpp +++ b/dbms/src/Flash/EstablishCall.cpp @@ -206,7 +206,13 @@ void EstablishCallData::writeDone(String msg, const grpc::Status & status) if (async_tunnel_sender) { - LOG_INFO(async_tunnel_sender->getLogger(), "connection for {} cost {} ms, including {} ms to waiting task.", async_tunnel_sender->getTunnelId(), stopwatch->elapsedMilliseconds(), waiting_task_time_ms); + auto time = stopwatch->elapsedMilliseconds(); + LOG_IMPL(async_tunnel_sender->getLogger(), + msg.empty() && time < 1000 ? Poco::Message::PRIO_DEBUG : Poco::Message::PRIO_INFORMATION, + "connection for {} cost {} ms, including {} ms to waiting task.", + async_tunnel_sender->getTunnelId(), + time, + waiting_task_time_ms); RUNTIME_ASSERT(!async_tunnel_sender->isConsumerFinished(), async_tunnel_sender->getLogger(), "tunnel {} consumer finished in advance", async_tunnel_sender->getTunnelId()); diff --git a/dbms/src/Flash/FlashService.cpp b/dbms/src/Flash/FlashService.cpp index 687e078cf37..8a1e441cb15 100644 --- a/dbms/src/Flash/FlashService.cpp +++ b/dbms/src/Flash/FlashService.cpp @@ -115,7 +115,7 @@ grpc::Status FlashService::Coprocessor( CPUAffinityManager::getInstance().bindSelfGrpcThread(); bool is_remote_read = getClientMetaVarWithDefault(grpc_context, "is_remote_read", "") == "true"; auto log_level = is_remote_read ? Poco::Message::PRIO_INFORMATION : Poco::Message::PRIO_DEBUG; - LOG_IMPL(log, log_level, "Handling coprocessor request, is_remote_read: {}, start ts: {}, region info: {}, region epoch: {}", is_remote_read, request->start_ts(), request->context().region_id(), request->context().region_epoch().DebugString()); + LOG_IMPL(log, log_level, "Handling coprocessor request, is_remote_read: {}, start ts: {}, region id: {}, region epoch: {}", is_remote_read, request->start_ts(), request->context().region_id(), request->context().region_epoch().DebugString()); auto check_result = checkGrpcContext(grpc_context); if (!check_result.ok()) @@ -165,10 +165,10 @@ grpc::Status FlashService::Coprocessor( return grpc::Status::OK; } } - + if (wait_ms > 1000) log_level = Poco::Message::PRIO_INFORMATION; - LOG_IMPL(log, log_level, "Begin process cop request after wait {} ms, start ts: {}, region info: {}, region epoch: {}", wait_ms, request->start_ts(), request->context().region_id(), request->context().region_epoch().DebugString()); + LOG_IMPL(log, log_level, "Begin process cop request after wait {} ms, start ts: {}, region id: {}, region epoch: {}", wait_ms, request->start_ts(), request->context().region_id(), request->context().region_epoch().DebugString()); auto [db_context, status] = createDBContext(grpc_context); if (!status.ok()) diff --git a/dbms/src/Flash/Mpp/MPPTask.cpp b/dbms/src/Flash/Mpp/MPPTask.cpp index 482e2eb0426..14a5a1bc962 100644 --- a/dbms/src/Flash/Mpp/MPPTask.cpp +++ b/dbms/src/Flash/Mpp/MPPTask.cpp @@ -382,7 +382,10 @@ void MPPTask::runImpl() mpp_task_statistics.start(); auto result = query_executor_holder->execute(); - LOG_INFO(log, "mpp task finish execute, success: {}", result.is_success); + auto log_level = Poco::Message::PRIO_DEBUG; + if (!result.is_success || status != RUNNING) + log_level = Poco::Message::PRIO_INFORMATION; + LOG_IMPL(log, log_level, "mpp task finish execute, success: {}, status: {}", result.is_success, magic_enum::enum_name(status.load())); if (likely(result.is_success)) { // finish receiver diff --git a/dbms/src/Flash/Mpp/MPPTaskStatistics.cpp b/dbms/src/Flash/Mpp/MPPTaskStatistics.cpp index f0436278d12..289c53dc70c 100644 --- a/dbms/src/Flash/Mpp/MPPTaskStatistics.cpp +++ b/dbms/src/Flash/Mpp/MPPTaskStatistics.cpp @@ -94,8 +94,10 @@ const BaseRuntimeStatistics & MPPTaskStatistics::collectRuntimeStatistics() void MPPTaskStatistics::logTracingJson() { - LOG_INFO( + LOG_IMPL( logger, + /// don't use info log for initializing status since it does not contains too many information + status == INITIALIZING ? Poco::Message::PRIO_DEBUG : Poco::Message::PRIO_INFORMATION, R"({{"query_tso":{},"task_id":{},"is_root":{},"sender_executor_id":"{}","executors":{},"host":"{}")" R"(,"task_init_timestamp":{},"task_start_timestamp":{},"task_end_timestamp":{})" R"(,"compile_start_timestamp":{},"compile_end_timestamp":{})" diff --git a/dbms/src/Interpreters/executeQuery.cpp b/dbms/src/Interpreters/executeQuery.cpp index ce3ec0107ac..a3852c6224e 100644 --- a/dbms/src/Interpreters/executeQuery.cpp +++ b/dbms/src/Interpreters/executeQuery.cpp @@ -436,7 +436,7 @@ void logQueryPipeline(const LoggerPtr & logger, const BlockInputStreamPtr & in) in->dumpTree(log_buffer); return log_buffer.toString(); }; - LOG_DEBUG(logger, pipeline_log_str()); + LOG_INFO(logger, pipeline_log_str()); } BlockIO executeQuery(