refine log (pingcap#8579)

ref pingcap#6233, close pingcap#8592
JaySon-Huang · Dec 27, 2023 · cea7c80 · cea7c80
1 parent 03c3c49
commit cea7c80
Show file tree

Hide file tree

Showing 8 changed files with 34 additions and 16 deletions.
diff --git 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
@@ -1443,7 +1443,7 @@ std::unordered_map<TableID, DAGStorageInterpreter::StorageWithStructureLock> DAG
         tmt.getSchemaSyncerManager()->syncTableSchema(context, keyspace_id, table_id);
         auto schema_sync_cost
             = std::chrono::duration_cast<std::chrono::milliseconds>(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<TableID, DAGStorageInterpreter::StorageWithStructureLock> 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<std::chrono::milliseconds>(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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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)