From cea7c80823e05173db7983bd6eecf0b81dc96761 Mon Sep 17 00:00:00 2001 From: xufei Date: Wed, 27 Dec 2023 10:22:57 +0800 Subject: [PATCH] refine log (#8579) ref pingcap/tiflash#6233, close pingcap/tiflash#8592 --- dbms/src/Core/OperatorSpillContext.cpp | 3 ++- dbms/src/Flash/Coprocessor/DAGStorageInterpreter.cpp | 11 ++++++++--- dbms/src/Flash/EstablishCall.cpp | 7 +++++-- dbms/src/Flash/Mpp/MPPTask.cpp | 8 ++++++-- dbms/src/Flash/Mpp/MPPTaskStatistics.cpp | 4 +++- dbms/src/Flash/Mpp/MPPTunnel.h | 4 +++- .../Flash/ResourceControl/LocalAdmissionController.h | 6 +++--- dbms/src/Interpreters/Aggregator.cpp | 7 ++++--- 8 files changed, 34 insertions(+), 16 deletions(-) diff --git a/dbms/src/Core/OperatorSpillContext.cpp b/dbms/src/Core/OperatorSpillContext.cpp index 3237fb2cb19..ade61eeeda1 100644 --- a/dbms/src/Core/OperatorSpillContext.cpp +++ b/dbms/src/Core/OperatorSpillContext.cpp @@ -47,7 +47,8 @@ void OperatorSpillContext::markSpilled() void OperatorSpillContext::finishSpillableStage() { - LOG_INFO(log, "Operator finish spill stage"); + if (isSpillEnabled()) + LOG_INFO(log, "Operator finish spill stage"); in_spillable_stage = false; } diff --git a/dbms/src/Flash/Coprocessor/DAGStorageInterpreter.cpp b/dbms/src/Flash/Coprocessor/DAGStorageInterpreter.cpp index 7fe083c0934..2b0a8373422 100644 --- a/dbms/src/Flash/Coprocessor/DAGStorageInterpreter.cpp +++ b/dbms/src/Flash/Coprocessor/DAGStorageInterpreter.cpp @@ -1443,7 +1443,7 @@ std::unordered_map DAG tmt.getSchemaSyncerManager()->syncTableSchema(context, keyspace_id, table_id); auto schema_sync_cost = std::chrono::duration_cast(Clock::now() - start_time).count(); - LOG_INFO( + LOG_DEBUG( log, "Table schema sync done, keyspace={} table_id={} cost={} ms", keyspace_id, @@ -1455,23 +1455,28 @@ std::unordered_map DAG auto [storages, locks, need_sync_table_ids] = get_and_lock_storages(false); if (need_sync_table_ids.empty()) { - LOG_INFO(log, "OK, no syncing required."); + LOG_DEBUG(log, "OK, no syncing required."); } else /// If first try failed, sync schema and try again. { LOG_INFO(log, "not OK, syncing schemas."); + auto start_time = Clock::now(); for (auto & table_id : need_sync_table_ids) { sync_schema(table_id); } + auto schema_sync_cost + = std::chrono::duration_cast(Clock::now() - start_time).count(); + + LOG_INFO(log, "syncing schemas done, time cost = {} ms.", schema_sync_cost); std::tie(storages, locks, need_sync_table_ids) = get_and_lock_storages(true); if (need_sync_table_ids.empty()) { - LOG_INFO(log, "OK after syncing."); + LOG_DEBUG(log, "OK after syncing."); } else throw TiFlashException("Shouldn't reach here", Errors::Coprocessor::Internal); diff --git a/dbms/src/Flash/EstablishCall.cpp b/dbms/src/Flash/EstablishCall.cpp index 001ad0d6d32..2ace85bd828 100644 --- a/dbms/src/Flash/EstablishCall.cpp +++ b/dbms/src/Flash/EstablishCall.cpp @@ -242,11 +242,14 @@ void EstablishCallData::writeDone(String msg, const grpc::Status & status) if (async_tunnel_sender) { - LOG_INFO( + auto time = stopwatch->elapsedMilliseconds(); + LOG_IMPL( async_tunnel_sender->getLogger(), + /// if time cost is less than 1s and there is no error, use debug log level + msg.empty() && time < 1000 ? Poco::Message::PRIO_DEBUG : Poco::Message::PRIO_INFORMATION, "async connection for {} cost {} ms, including {} ms to wait task.", async_tunnel_sender->getTunnelId(), - stopwatch->elapsedMilliseconds(), + time, waiting_task_time_ms); RUNTIME_ASSERT( diff --git a/dbms/src/Flash/Mpp/MPPTask.cpp b/dbms/src/Flash/Mpp/MPPTask.cpp index 1f08bb7c7ee..33216db979a 100644 --- a/dbms/src/Flash/Mpp/MPPTask.cpp +++ b/dbms/src/Flash/Mpp/MPPTask.cpp @@ -562,14 +562,18 @@ void MPPTask::runImpl() #endif auto result = query_executor_holder->execute(); - LOG_INFO( + 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, is_success: {}, status: {}", result.is_success, magic_enum::enum_name(status.load())); auto cpu_ru = query_executor_holder->collectRequestUnit(); auto read_ru = dag_context->getReadRU(); - LOG_INFO(log, "mpp finish with request unit: cpu={} read={}", cpu_ru, read_ru); + LOG_DEBUG(log, "mpp finish with request unit: cpu={} read={}", cpu_ru, read_ru); GET_METRIC(tiflash_compute_request_unit, type_mpp).Increment(cpu_ru + read_ru); mpp_task_statistics.setRU(cpu_ru, read_ru); diff --git a/dbms/src/Flash/Mpp/MPPTaskStatistics.cpp b/dbms/src/Flash/Mpp/MPPTaskStatistics.cpp index cde2e6fe3c0..53da8119bf6 100644 --- a/dbms/src/Flash/Mpp/MPPTaskStatistics.cpp +++ b/dbms/src/Flash/Mpp/MPPTaskStatistics.cpp @@ -105,8 +105,10 @@ tipb::TiFlashExecutionInfo MPPTaskStatistics::genTiFlashExecutionInfo() void MPPTaskStatistics::logTracingJson() { - LOG_INFO( + LOG_IMPL( log, + /// 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/Flash/Mpp/MPPTunnel.h b/dbms/src/Flash/Mpp/MPPTunnel.h index 94dabeb7449..58062b7a170 100644 --- a/dbms/src/Flash/Mpp/MPPTunnel.h +++ b/dbms/src/Flash/Mpp/MPPTunnel.h @@ -353,8 +353,10 @@ class LocalTunnelSenderV2 : public TunnelSender { consumer_state.setMsg(local_err_msg); local_request_handler.writeDone(meet_error, local_err_msg); - LOG_INFO( + auto time = local_request_handler.getTotalElapsedTime(); + LOG_IMPL( log, + !meet_error && time < 1000 ? Poco::Message::PRIO_DEBUG : Poco::Message::PRIO_INFORMATION, "connection for {} cost {} ms, including {} ms to wait task.", tunnel_id, local_request_handler.getTotalElapsedTime(), diff --git a/dbms/src/Flash/ResourceControl/LocalAdmissionController.h b/dbms/src/Flash/ResourceControl/LocalAdmissionController.h index 2fd2cb2a9cd..9a2b5392c39 100644 --- a/dbms/src/Flash/ResourceControl/LocalAdmissionController.h +++ b/dbms/src/Flash/ResourceControl/LocalAdmissionController.h @@ -477,7 +477,7 @@ class LocalAdmissionController final : private boost::noncopyable ResourceGroupPtr group = findResourceGroup(name); if unlikely (!group) { - LOG_INFO(log, "cannot get priority for {}, maybe it has been deleted", name); + LOG_DEBUG(log, "cannot get priority for {}, maybe it has been deleted", name); return 0; } return group->estWaitDuraMS(DEFAULT_FETCH_GAC_INTERVAL_MS); @@ -494,7 +494,7 @@ class LocalAdmissionController final : private boost::noncopyable ResourceGroupPtr group = findResourceGroup(name); if unlikely (!group) { - LOG_INFO(log, "cannot get priority for {}, maybe it has been deleted", name); + LOG_DEBUG(log, "cannot get priority for {}, maybe it has been deleted", name); return std::nullopt; } @@ -613,7 +613,7 @@ class LocalAdmissionController final : private boost::noncopyable ResourceGroupPtr group = findResourceGroup(name); if unlikely (!group) { - LOG_INFO(log, "cannot consume ru for {}, maybe it has been deleted", name); + LOG_DEBUG(log, "cannot consume ru for {}, maybe it has been deleted", name); return; } diff --git a/dbms/src/Interpreters/Aggregator.cpp b/dbms/src/Interpreters/Aggregator.cpp index 231985a5f01..00d982bdbf7 100644 --- a/dbms/src/Interpreters/Aggregator.cpp +++ b/dbms/src/Interpreters/Aggregator.cpp @@ -341,9 +341,10 @@ Aggregator::Aggregator( { params.setMaxBytesBeforeExternalGroupBy(0); agg_spill_context->disableSpill(); - LOG_WARNING( - log, - "Aggregation does not support spill because aggregator hash table does not support two level"); + if (method_chosen != AggregatedDataVariants::Type::without_key) + LOG_WARNING( + log, + "Aggregation does not support spill because aggregator hash table does not support two level"); } } if (register_operator_spill_context != nullptr)