You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@doris.apache.org by yi...@apache.org on 2023/07/01 04:18:29 UTC
[doris] branch master updated: [Chore](metrics) remove trace metrics code using runtime profile instead (#21394)
This is an automated email from the ASF dual-hosted git repository.
yiguolei pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/doris.git
The following commit(s) were added to refs/heads/master by this push:
new 1fe04b7242 [Chore](metrics) remove trace metrics code using runtime profile instead (#21394)
1fe04b7242 is described below
commit 1fe04b7242961f3ef067d9adcc0057f4155ac16e
Author: ZhangYu0123 <67...@users.noreply.github.com>
AuthorDate: Sat Jul 1 12:18:23 2023 +0800
[Chore](metrics) remove trace metrics code using runtime profile instead (#21394)
* commit
* fix
* format
---
be/src/agent/task_worker_pool.cpp | 4 +-
be/src/olap/base_compaction.cpp | 2 +-
be/src/olap/compaction.cpp | 51 +++--
be/src/olap/compaction.h | 17 ++
be/src/olap/cumulative_compaction.cpp | 2 +-
be/src/olap/merger.cpp | 3 -
be/src/olap/tablet.cpp | 43 ++--
be/src/util/trace.cpp | 268 -----------------------
be/src/util/trace.h | 217 ------------------
be/src/util/trace_metrics.cpp | 70 ------
be/src/util/trace_metrics.h | 90 --------
docs/en/docs/admin-manual/config/be-config.md | 14 +-
docs/zh-CN/docs/admin-manual/config/be-config.md | 14 +-
13 files changed, 104 insertions(+), 691 deletions(-)
diff --git a/be/src/agent/task_worker_pool.cpp b/be/src/agent/task_worker_pool.cpp
index bfddfbff97..030f50b364 100644
--- a/be/src/agent/task_worker_pool.cpp
+++ b/be/src/agent/task_worker_pool.cpp
@@ -1214,15 +1214,13 @@ void CreateTableTaskPool::_create_tablet_worker_thread_callback() {
_tasks.pop_front();
}
const TCreateTabletReq& create_tablet_req = agent_task_req.create_tablet_req;
- scoped_refptr<Trace> trace(new Trace);
MonotonicStopWatch watch;
watch.start();
SCOPED_CLEANUP({
if (watch.elapsed_time() / 1e9 > config::agent_task_trace_threshold_sec) {
- LOG(WARNING) << "Trace:" << std::endl << trace->DumpToString(Trace::INCLUDE_ALL);
+ LOG(WARNING) << "create tablet cost " << watch.elapsed_time() / 1e9;
}
});
- ADOPT_TRACE(trace.get());
DorisMetrics::instance()->create_tablet_requests_total->increment(1);
VLOG_NOTICE << "start to create tablet " << create_tablet_req.tablet_id;
diff --git a/be/src/olap/base_compaction.cpp b/be/src/olap/base_compaction.cpp
index d7b186e230..40f4ac925c 100644
--- a/be/src/olap/base_compaction.cpp
+++ b/be/src/olap/base_compaction.cpp
@@ -55,7 +55,7 @@ Status BaseCompaction::prepare_compact() {
// 1. pick rowsets to compact
RETURN_IF_ERROR(pick_rowsets_to_compact());
- TRACE_COUNTER_INCREMENT("input_rowsets_count", _input_rowsets.size());
+ COUNTER_UPDATE(_input_rowsets_counter, _input_rowsets.size());
_tablet->set_clone_occurred(false);
return Status::OK();
diff --git a/be/src/olap/compaction.cpp b/be/src/olap/compaction.cpp
index 5354605108..11ea83ecc1 100644
--- a/be/src/olap/compaction.cpp
+++ b/be/src/olap/compaction.cpp
@@ -68,10 +68,28 @@ Compaction::Compaction(const TabletSharedPtr& tablet, const std::string& label)
_input_index_size(0),
_state(CompactionState::INITED) {
_mem_tracker = std::make_shared<MemTrackerLimiter>(MemTrackerLimiter::Type::COMPACTION, label);
+ init_profile(label);
}
Compaction::~Compaction() {}
+void Compaction::init_profile(const std::string& label) {
+ _profile = std::make_unique<RuntimeProfile>(label);
+
+ _input_rowsets_data_size_counter =
+ ADD_COUNTER(_profile, "input_rowsets_data_size", TUnit::BYTES);
+ _input_rowsets_counter = ADD_COUNTER(_profile, "input_rowsets_count", TUnit::UNIT);
+ _input_row_num_counter = ADD_COUNTER(_profile, "input_row_num", TUnit::UNIT);
+ _input_segments_num_counter = ADD_COUNTER(_profile, "input_segments_num", TUnit::UNIT);
+ _merged_rows_counter = ADD_COUNTER(_profile, "merged_rows", TUnit::UNIT);
+ _filtered_rows_counter = ADD_COUNTER(_profile, "filtered_rows", TUnit::UNIT);
+ _output_rowset_data_size_counter =
+ ADD_COUNTER(_profile, "output_rowset_data_size", TUnit::BYTES);
+ _output_row_num_counter = ADD_COUNTER(_profile, "output_row_num", TUnit::UNIT);
+ _output_segments_num_counter = ADD_COUNTER(_profile, "output_segments_num", TUnit::UNIT);
+ _merge_rowsets_latency_timer = ADD_TIMER(_profile, "merge_rowsets_latency");
+}
+
Status Compaction::compact() {
RETURN_IF_ERROR(prepare_compact());
RETURN_IF_ERROR(execute_compact());
@@ -208,9 +226,9 @@ void Compaction::build_basic_info() {
_input_row_num += rowset->num_rows();
_input_num_segments += rowset->num_segments();
}
- TRACE_COUNTER_INCREMENT("input_rowsets_data_size", _input_rowsets_size);
- TRACE_COUNTER_INCREMENT("input_row_num", _input_row_num);
- TRACE_COUNTER_INCREMENT("input_segments_num", _input_num_segments);
+ COUNTER_UPDATE(_input_rowsets_data_size_counter, _input_rowsets_size);
+ COUNTER_UPDATE(_input_row_num_counter, _input_row_num);
+ COUNTER_UPDATE(_input_segments_num_counter, _input_num_segments);
_output_version =
Version(_input_rowsets.front()->start_version(), _input_rowsets.back()->end_version());
@@ -315,13 +333,16 @@ Status Compaction::do_compaction_impl(int64_t permits) {
}
Status res;
- if (vertical_compaction) {
- res = Merger::vertical_merge_rowsets(_tablet, compaction_type(), _cur_tablet_schema,
- _input_rs_readers, _output_rs_writer.get(),
- get_avg_segment_rows(), &stats);
- } else {
- res = Merger::vmerge_rowsets(_tablet, compaction_type(), _cur_tablet_schema,
- _input_rs_readers, _output_rs_writer.get(), &stats);
+ {
+ SCOPED_TIMER(_merge_rowsets_latency_timer);
+ if (vertical_compaction) {
+ res = Merger::vertical_merge_rowsets(_tablet, compaction_type(), _cur_tablet_schema,
+ _input_rs_readers, _output_rs_writer.get(),
+ get_avg_segment_rows(), &stats);
+ } else {
+ res = Merger::vmerge_rowsets(_tablet, compaction_type(), _cur_tablet_schema,
+ _input_rs_readers, _output_rs_writer.get(), &stats);
+ }
}
if (!res.ok()) {
@@ -330,8 +351,8 @@ Status Compaction::do_compaction_impl(int64_t permits) {
<< ", output_version=" << _output_version;
return res;
}
- TRACE_COUNTER_INCREMENT("merged_rows", stats.merged_rows);
- TRACE_COUNTER_INCREMENT("filtered_rows", stats.filtered_rows);
+ COUNTER_UPDATE(_merged_rows_counter, stats.merged_rows);
+ COUNTER_UPDATE(_filtered_rows_counter, stats.filtered_rows);
_output_rowset = _output_rs_writer->build();
if (_output_rowset == nullptr) {
@@ -340,9 +361,9 @@ Status Compaction::do_compaction_impl(int64_t permits) {
return Status::Error<ROWSET_BUILDER_INIT>();
}
- TRACE_COUNTER_INCREMENT("output_rowset_data_size", _output_rowset->data_disk_size());
- TRACE_COUNTER_INCREMENT("output_row_num", _output_rowset->num_rows());
- TRACE_COUNTER_INCREMENT("output_segments_num", _output_rowset->num_segments());
+ COUNTER_UPDATE(_output_rowset_data_size_counter, _output_rowset->data_disk_size());
+ COUNTER_UPDATE(_output_row_num_counter, _output_rowset->num_rows());
+ COUNTER_UPDATE(_output_segments_num_counter, _output_rowset->num_segments());
// 3. check correctness
RETURN_IF_ERROR(check_correctness(stats));
diff --git a/be/src/olap/compaction.h b/be/src/olap/compaction.h
index 737f4bf01c..bed9ae403f 100644
--- a/be/src/olap/compaction.h
+++ b/be/src/olap/compaction.h
@@ -62,6 +62,8 @@ public:
RowsetSharedPtr output_rowset();
#endif
+ RuntimeProfile* runtime_profile() const { return _profile.get(); }
+
protected:
virtual Status pick_rowsets_to_compact() = 0;
virtual std::string compaction_name() const = 0;
@@ -90,6 +92,8 @@ protected:
bool is_rowset_tidy(std::string& pre_max_key, const RowsetSharedPtr& rhs);
void build_basic_info();
+ void init_profile(const std::string& label);
+
protected:
// the root tracker for this compaction
std::shared_ptr<MemTrackerLimiter> _mem_tracker;
@@ -115,6 +119,19 @@ protected:
RowIdConversion _rowid_conversion;
TabletSchemaSPtr _cur_tablet_schema;
+ std::unique_ptr<RuntimeProfile> _profile;
+
+ RuntimeProfile::Counter* _input_rowsets_data_size_counter = nullptr;
+ RuntimeProfile::Counter* _input_rowsets_counter = nullptr;
+ RuntimeProfile::Counter* _input_row_num_counter = nullptr;
+ RuntimeProfile::Counter* _input_segments_num_counter = nullptr;
+ RuntimeProfile::Counter* _merged_rows_counter = nullptr;
+ RuntimeProfile::Counter* _filtered_rows_counter = nullptr;
+ RuntimeProfile::Counter* _output_rowset_data_size_counter = nullptr;
+ RuntimeProfile::Counter* _output_row_num_counter = nullptr;
+ RuntimeProfile::Counter* _output_segments_num_counter = nullptr;
+ RuntimeProfile::Counter* _merge_rowsets_latency_timer = nullptr;
+
DISALLOW_COPY_AND_ASSIGN(Compaction);
};
diff --git a/be/src/olap/cumulative_compaction.cpp b/be/src/olap/cumulative_compaction.cpp
index 9c4f5bae91..ad2bfd841a 100644
--- a/be/src/olap/cumulative_compaction.cpp
+++ b/be/src/olap/cumulative_compaction.cpp
@@ -60,7 +60,7 @@ Status CumulativeCompaction::prepare_compact() {
// 2. pick rowsets to compact
RETURN_IF_ERROR(pick_rowsets_to_compact());
- TRACE_COUNTER_INCREMENT("input_rowsets_count", _input_rowsets.size());
+ COUNTER_UPDATE(_input_rowsets_counter, _input_rowsets.size());
_tablet->set_clone_occurred(false);
return Status::OK();
diff --git a/be/src/olap/merger.cpp b/be/src/olap/merger.cpp
index 4e8f43f1ce..ff01c3bd66 100644
--- a/be/src/olap/merger.cpp
+++ b/be/src/olap/merger.cpp
@@ -45,7 +45,6 @@
#include "olap/tablet.h"
#include "olap/utils.h"
#include "util/slice.h"
-#include "util/trace.h"
#include "vec/core/block.h"
#include "vec/olap/block_reader.h"
#include "vec/olap/vertical_block_reader.h"
@@ -57,8 +56,6 @@ Status Merger::vmerge_rowsets(TabletSharedPtr tablet, ReaderType reader_type,
TabletSchemaSPtr cur_tablet_schema,
const std::vector<RowsetReaderSharedPtr>& src_rowset_readers,
RowsetWriter* dst_rowset_writer, Statistics* stats_output) {
- TRACE_COUNTER_SCOPE_LATENCY_US("merge_rowsets_latency_us");
-
vectorized::BlockReader reader;
TabletReader::ReaderParams reader_params;
reader_params.tablet = tablet;
diff --git a/be/src/olap/tablet.cpp b/be/src/olap/tablet.cpp
index 2d49643235..4eb124a135 100644
--- a/be/src/olap/tablet.cpp
+++ b/be/src/olap/tablet.cpp
@@ -1670,15 +1670,18 @@ Status Tablet::prepare_compaction_and_calculate_permits(CompactionType compactio
TabletSharedPtr tablet, int64_t* permits) {
std::vector<RowsetSharedPtr> compaction_rowsets;
if (compaction_type == CompactionType::CUMULATIVE_COMPACTION) {
- scoped_refptr<Trace> trace(new Trace);
MonotonicStopWatch watch;
watch.start();
SCOPED_CLEANUP({
- if (watch.elapsed_time() / 1e9 > config::cumulative_compaction_trace_threshold) {
- LOG(WARNING) << "Trace:" << std::endl << trace->DumpToString(Trace::INCLUDE_ALL);
+ if (!config::disable_compaction_trace_log &&
+ watch.elapsed_time() / 1e9 > config::cumulative_compaction_trace_threshold) {
+ std::stringstream ss;
+ _cumulative_compaction->runtime_profile()->pretty_print(&ss);
+ LOG(WARNING) << "prepare cumulative compaction cost " << watch.elapsed_time() / 1e9
+ << std::endl
+ << ss.str();
}
});
- ADOPT_TRACE(trace.get());
StorageEngine::instance()->create_cumulative_compaction(tablet, _cumulative_compaction);
DorisMetrics::instance()->cumulative_compaction_request_total->increment(1);
@@ -1698,15 +1701,18 @@ Status Tablet::prepare_compaction_and_calculate_permits(CompactionType compactio
compaction_rowsets = _cumulative_compaction->get_input_rowsets();
} else {
DCHECK_EQ(compaction_type, CompactionType::BASE_COMPACTION);
- scoped_refptr<Trace> trace(new Trace);
MonotonicStopWatch watch;
watch.start();
SCOPED_CLEANUP({
- if (watch.elapsed_time() / 1e9 > config::base_compaction_trace_threshold) {
- LOG(WARNING) << "Trace:" << std::endl << trace->DumpToString(Trace::INCLUDE_ALL);
+ if (!config::disable_compaction_trace_log &&
+ watch.elapsed_time() / 1e9 > config::base_compaction_trace_threshold) {
+ std::stringstream ss;
+ _base_compaction->runtime_profile()->pretty_print(&ss);
+ LOG(WARNING) << "prepare base compaction cost " << watch.elapsed_time() / 1e9
+ << std::endl
+ << ss.str();
}
});
- ADOPT_TRACE(trace.get());
StorageEngine::instance()->create_base_compaction(tablet, _base_compaction);
DorisMetrics::instance()->base_compaction_request_total->increment(1);
@@ -1734,9 +1740,6 @@ Status Tablet::prepare_compaction_and_calculate_permits(CompactionType compactio
Status Tablet::prepare_single_replica_compaction(TabletSharedPtr tablet,
CompactionType compaction_type) {
- scoped_refptr<Trace> trace(new Trace);
- ADOPT_TRACE(trace.get());
-
StorageEngine::instance()->create_single_replica_compaction(tablet, _single_replica_compaction,
compaction_type);
Status res = _single_replica_compaction->prepare_compact();
@@ -1749,8 +1752,6 @@ Status Tablet::prepare_single_replica_compaction(TabletSharedPtr tablet,
}
void Tablet::execute_single_replica_compaction(CompactionType compaction_type) {
- scoped_refptr<Trace> trace(new Trace);
- ADOPT_TRACE(trace.get());
Status res = _single_replica_compaction->execute_compact();
if (!res.ok()) {
if (compaction_type == CompactionType::CUMULATIVE_COMPACTION) {
@@ -1788,16 +1789,18 @@ std::vector<Version> Tablet::get_all_versions() {
void Tablet::execute_compaction(CompactionType compaction_type) {
if (compaction_type == CompactionType::CUMULATIVE_COMPACTION) {
- scoped_refptr<Trace> trace(new Trace);
MonotonicStopWatch watch;
watch.start();
SCOPED_CLEANUP({
if (!config::disable_compaction_trace_log &&
watch.elapsed_time() / 1e9 > config::cumulative_compaction_trace_threshold) {
- LOG(WARNING) << "Trace:" << std::endl << trace->DumpToString(Trace::INCLUDE_ALL);
+ std::stringstream ss;
+ _cumulative_compaction->runtime_profile()->pretty_print(&ss);
+ LOG(WARNING) << "execute cumulative compaction cost " << watch.elapsed_time() / 1e9
+ << std::endl
+ << ss.str();
}
});
- ADOPT_TRACE(trace.get());
Status res = _cumulative_compaction->execute_compact();
if (!res.ok()) {
@@ -1810,16 +1813,18 @@ void Tablet::execute_compaction(CompactionType compaction_type) {
set_last_cumu_compaction_failure_time(0);
} else {
DCHECK_EQ(compaction_type, CompactionType::BASE_COMPACTION);
- scoped_refptr<Trace> trace(new Trace);
MonotonicStopWatch watch;
watch.start();
SCOPED_CLEANUP({
if (!config::disable_compaction_trace_log &&
watch.elapsed_time() / 1e9 > config::base_compaction_trace_threshold) {
- LOG(WARNING) << "Trace:" << std::endl << trace->DumpToString(Trace::INCLUDE_ALL);
+ std::stringstream ss;
+ _base_compaction->runtime_profile()->pretty_print(&ss);
+ LOG(WARNING) << "execute base compaction cost " << watch.elapsed_time() / 1e9
+ << std::endl
+ << ss.str();
}
});
- ADOPT_TRACE(trace.get());
Status res = _base_compaction->execute_compact();
if (!res.ok()) {
diff --git a/be/src/util/trace.cpp b/be/src/util/trace.cpp
deleted file mode 100644
index 01b396ee1d..0000000000
--- a/be/src/util/trace.cpp
+++ /dev/null
@@ -1,268 +0,0 @@
-// Licensed to the Apache Software Foundation (ASF) under one
-// or more contributor license agreements. See the NOTICE file
-// distributed with this work for additional information
-// regarding copyright ownership. The ASF licenses this file
-// to you under the Apache License, Version 2.0 (the
-// "License"); you may not use this file except in compliance
-// with the License. You may obtain a copy of the License at
-//
-// http://www.apache.org/licenses/LICENSE-2.0
-//
-// Unless required by applicable law or agreed to in writing,
-// software distributed under the License is distributed on an
-// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
-// KIND, either express or implied. See the License for the
-// specific language governing permissions and limitations
-// under the License.
-
-#include "util/trace.h"
-
-#include <glog/logging.h>
-#include <rapidjson/encodings.h>
-#include <stdlib.h>
-#include <time.h>
-
-#include <algorithm>
-#include <cstring>
-#include <iomanip>
-#include <iostream>
-#include <iterator>
-#include <map>
-#include <mutex>
-#include <string>
-#include <utility>
-#include <vector>
-
-#include "gutil/stringprintf.h"
-#include "gutil/strings/substitute.h"
-//#include "util/memory/arena.h"
-
-using std::pair;
-using std::string;
-using std::vector;
-using strings::internal::SubstituteArg;
-
-namespace doris {
-
-// Format a timestamp in the same format as used by GLog.
-static std::string FormatTimestampForLog(int64_t micros_since_epoch) {
- time_t secs_since_epoch = micros_since_epoch / 1000000;
- int usecs = micros_since_epoch % 1000000;
- struct tm tm_time;
- localtime_r(&secs_since_epoch, &tm_time);
-
- return StringPrintf("%02d%02d %02d:%02d:%02d.%06d", 1 + tm_time.tm_mon, tm_time.tm_mday,
- tm_time.tm_hour, tm_time.tm_min, tm_time.tm_sec, usecs);
-}
-
-__thread Trace* Trace::threadlocal_trace_;
-
-Trace::Trace()
- : // arena_(new ThreadSafeArena(1024)),
- entries_head_(nullptr),
- entries_tail_(nullptr) {
- // We expect small allocations from our Arena so no need to have
- // a large arena component. Small allocations are more likely to
- // come out of thread cache and be fast.
- // arena_->SetMaxBufferSize(4096);
-}
-
-// Struct which precedes each entry in the trace.
-struct TraceEntry {
- int64_t timestamp_micros;
-
- // The source file and line number which generated the trace message.
- const char* file_path;
- int line_number;
-
- uint32_t message_len;
- TraceEntry* next;
-
- // The actual trace message follows the entry header.
- char* message() { return reinterpret_cast<char*>(this) + sizeof(*this); }
-};
-
-Trace::~Trace() {
- while (entries_head_ != nullptr) {
- TraceEntry* tmp = entries_head_;
- entries_head_ = entries_head_->next;
- free(tmp);
- }
-}
-
-// Get the part of filepath after the last path separator.
-// (Doesn't modify filepath, contrary to basename() in libgen.h.)
-// Borrowed from glog.
-static const char* const_basename(const char* filepath) {
- const char* base = strrchr(filepath, '/');
-#ifdef OS_WINDOWS // Look for either path separator in Windows
- if (!base) base = strrchr(filepath, '\\');
-#endif
- return base ? (base + 1) : filepath;
-}
-
-void Trace::SubstituteAndTrace(const char* file_path, int line_number, StringPiece format,
- const SubstituteArg& arg0, const SubstituteArg& arg1,
- const SubstituteArg& arg2, const SubstituteArg& arg3,
- const SubstituteArg& arg4, const SubstituteArg& arg5,
- const SubstituteArg& arg6, const SubstituteArg& arg7,
- const SubstituteArg& arg8, const SubstituteArg& arg9) {
- const SubstituteArg* const args_array[] = {&arg0, &arg1, &arg2, &arg3, &arg4, &arg5,
- &arg6, &arg7, &arg8, &arg9, nullptr};
-
- int msg_len = strings::internal::SubstitutedSize(format, args_array);
- TraceEntry* entry = NewEntry(msg_len, file_path, line_number);
- SubstituteToBuffer(format, args_array, entry->message());
- AddEntry(entry);
-}
-
-TraceEntry* Trace::NewEntry(int msg_len, const char* file_path, int line_number) {
- int size = sizeof(TraceEntry) + msg_len;
- //uint8_t* dst = reinterpret_cast<uint8_t*>(arena_->AllocateBytes(size));
- uint8_t* dst = reinterpret_cast<uint8_t*>(malloc(size));
- TraceEntry* entry = reinterpret_cast<TraceEntry*>(dst);
- entry->timestamp_micros = GetCurrentTimeMicros();
- entry->message_len = msg_len;
- entry->file_path = file_path;
- entry->line_number = line_number;
- return entry;
-}
-
-void Trace::AddEntry(TraceEntry* entry) {
- std::lock_guard<SpinLock> l(lock_);
- entry->next = nullptr;
-
- if (entries_tail_ != nullptr) {
- entries_tail_->next = entry;
- } else {
- DCHECK(entries_head_ == nullptr);
- entries_head_ = entry;
- }
- entries_tail_ = entry;
-}
-
-void Trace::Dump(std::ostream* out, int flags) const {
- // Gather a copy of the list of entries under the lock. This is fast
- // enough that we aren't worried about stalling concurrent tracers
- // (whereas doing the logging itself while holding the lock might be
- // too slow, if the output stream is a file, for example).
- std::vector<TraceEntry*> entries;
- std::vector<pair<StringPiece, scoped_refptr<Trace>>> child_traces;
- {
- std::lock_guard<SpinLock> l(lock_);
- for (TraceEntry* cur = entries_head_; cur != nullptr; cur = cur->next) {
- entries.push_back(cur);
- }
-
- child_traces = child_traces_;
- }
-
- // Save original flags.
- std::ios::fmtflags save_flags(out->flags());
-
- int64_t prev_usecs = 0;
- for (TraceEntry* e : entries) {
- // Log format borrowed from glog/logging.cc
- int64_t usecs_since_prev = 0;
- if (prev_usecs != 0) {
- usecs_since_prev = e->timestamp_micros - prev_usecs;
- }
- prev_usecs = e->timestamp_micros;
-
- using std::setw;
- *out << FormatTimestampForLog(e->timestamp_micros);
- *out << ' ';
- if (flags & INCLUDE_TIME_DELTAS) {
- out->fill(' ');
- *out << "(+" << setw(6) << usecs_since_prev << "us) ";
- }
- *out << const_basename(e->file_path) << ':' << e->line_number << "] ";
- out->write(reinterpret_cast<char*>(e) + sizeof(TraceEntry), e->message_len);
- *out << std::endl;
- }
-
- for (const auto& entry : child_traces) {
- const auto& t = entry.second;
- *out << "Related trace '" << entry.first << "':" << std::endl;
- *out << t->DumpToString(flags & (~INCLUDE_METRICS));
- }
-
- if (flags & INCLUDE_METRICS) {
- *out << "Metrics: " << MetricsAsJSON();
- }
-
- // Restore stream flags.
- out->flags(save_flags);
-}
-
-std::string Trace::DumpToString(int flags) const {
- std::ostringstream s;
- Dump(&s, flags);
- return s.str();
-}
-
-std::string Trace::MetricsAsJSON() const {
- // TODO(yingchun): simplify implement here, we could import JsonWriter in the future.
- rapidjson::StringBuffer buf;
- rapidjson::Writer<rapidjson::StringBuffer> jw(buf);
- MetricsToJSON(&jw);
- return buf.GetString();
-}
-
-void Trace::MetricsToJSON(rapidjson::Writer<rapidjson::StringBuffer>* jw) const {
- // Convert into a map with 'std::string' keys instead of 'const char*'
- // keys, so that the results are in a consistent (sorted) order.
- std::map<string, int64_t> counters;
- for (const auto& entry : metrics_.Get()) {
- counters[entry.first] = entry.second;
- }
-
- jw->StartObject();
- for (const auto& e : counters) {
- jw->String(e.first.c_str());
- jw->Int64(e.second);
- }
- std::vector<pair<StringPiece, scoped_refptr<Trace>>> child_traces;
- {
- std::lock_guard<SpinLock> l(lock_);
- child_traces = child_traces_;
- }
-
- if (!child_traces.empty()) {
- jw->String("child_traces");
- jw->StartArray();
-
- for (const auto& e : child_traces) {
- jw->StartArray();
- jw->String(e.first.data(), e.first.size());
- e.second->MetricsToJSON(jw);
- jw->EndArray();
- }
- jw->EndArray();
- }
- jw->EndObject();
-}
-
-void Trace::DumpCurrentTrace() {
- Trace* t = CurrentTrace();
- if (t == nullptr) {
- LOG(INFO) << "No trace is currently active.";
- return;
- }
- t->Dump(&std::cerr, true);
-}
-
-void Trace::AddChildTrace(StringPiece label, Trace* child_trace) {
- //CHECK(arena_->RelocateStringPiece(label, &label));
-
- std::lock_guard<SpinLock> l(lock_);
- scoped_refptr<Trace> ptr(child_trace);
- child_traces_.emplace_back(label, ptr);
-}
-
-std::vector<std::pair<StringPiece, scoped_refptr<Trace>>> Trace::ChildTraces() const {
- std::lock_guard<SpinLock> l(lock_);
- return child_traces_;
-}
-
-} // namespace doris
diff --git a/be/src/util/trace.h b/be/src/util/trace.h
index ea1f3e665c..30da779624 100644
--- a/be/src/util/trace.h
+++ b/be/src/util/trace.h
@@ -17,17 +17,7 @@
#pragma once
#include <butil/macros.h>
-#include <rapidjson/stringbuffer.h>
-#include <rapidjson/writer.h>
-#include <stdint.h>
-#include <chrono>
-#include <iosfwd>
-#include <string>
-#include <utility>
-#include <vector>
-
-#include "common/logging.h"
#include "gutil/ref_counted.h"
#include "gutil/strings/stringpiece.h"
#include "gutil/strings/substitute.h"
@@ -35,55 +25,6 @@
#include "util/scoped_cleanup.h"
#include "util/spinlock.h"
#include "util/time.h"
-#include "util/trace_metrics.h"
-
-namespace doris {
-class Trace;
-}
-
-// Adopt a Trace on the current thread for the duration of the current
-// scope. The old current Trace is restored when the scope is exited.
-//
-// 't' should be a Trace* pointer.
-#define ADOPT_TRACE(t) doris::ScopedAdoptTrace _adopt_trace(t);
-
-// Increment a counter associated with the current trace.
-//
-// Each trace contains a map of counters which can be used to keep
-// request-specific statistics. It is significantly faster to increment
-// a trace counter compared to logging a message. Additionally, having
-// slightly more structured information makes it easier to aggregate
-// and show information back to operators.
-//
-// NOTE: the 'counter_name' MUST be a string which stays alive forever.
-// Typically, this is a compile-time constant. If something other than
-// a constant is required, use TraceMetric::InternName() in order to
-// create a string which will last for the process lifetime. Of course,
-// these strings will never be cleaned up, so it's important to use this
-// judiciously.
-//
-// If no trace is active, this does nothing and does not evaluate its
-// parameters.
-#define TRACE_COUNTER_INCREMENT(counter_name, val) \
- do { \
- doris::Trace* _trace = doris::Trace::CurrentTrace(); \
- if (_trace) { \
- _trace->metrics()->Increment(counter_name, val); \
- } \
- } while (0)
-
-// Increment a counter for the amount of wall time spent in the current
-// scope. For example:
-//
-// void DoFoo() {
-// TRACE_COUNTER_SCOPE_LATENCY_US("foo_us");
-// ... do expensive Foo thing
-// }
-//
-// will result in a trace metric indicating the number of microseconds spent
-// in invocations of DoFoo().
-#define TRACE_COUNTER_SCOPE_LATENCY_US(counter_name) \
- ::doris::ScopedTraceLatencyCounter _scoped_latency(counter_name)
// If this scope times out, make a simple trace.
// It will log the cost time only.
@@ -110,161 +51,3 @@ class Trace;
stream << "Simple trace cost(us): " << VARNAME_LINENUM(cost_us); \
} \
})
-
-namespace doris {
-
-struct TraceEntry;
-
-// A trace for a request or other process. This supports collecting trace entries
-// from a number of threads, and later dumping the results to a stream.
-//
-// Callers should generally not add trace messages directly using the public
-// methods of this class. Rather, the TRACE(...) macros defined above should
-// be used such that file/line numbers are automatically included, etc.
-//
-// This class is thread-safe.
-class Trace : public RefCountedThreadSafe<Trace> {
-public:
- Trace();
-
- // Logs a message into the trace buffer.
- //
- // See strings::Substitute for details.
- //
- // N.B.: the file path passed here is not copied, so should be a static
- // constant (eg __FILE__).
- void SubstituteAndTrace(
- const char* filepath, int line_number, StringPiece format,
- const strings::internal::SubstituteArg& arg0 = strings::internal::SubstituteArg::NoArg,
- const strings::internal::SubstituteArg& arg1 = strings::internal::SubstituteArg::NoArg,
- const strings::internal::SubstituteArg& arg2 = strings::internal::SubstituteArg::NoArg,
- const strings::internal::SubstituteArg& arg3 = strings::internal::SubstituteArg::NoArg,
- const strings::internal::SubstituteArg& arg4 = strings::internal::SubstituteArg::NoArg,
- const strings::internal::SubstituteArg& arg5 = strings::internal::SubstituteArg::NoArg,
- const strings::internal::SubstituteArg& arg6 = strings::internal::SubstituteArg::NoArg,
- const strings::internal::SubstituteArg& arg7 = strings::internal::SubstituteArg::NoArg,
- const strings::internal::SubstituteArg& arg8 = strings::internal::SubstituteArg::NoArg,
- const strings::internal::SubstituteArg& arg9 = strings::internal::SubstituteArg::NoArg);
-
- // Dump the trace buffer to the given output stream.
- //
- enum {
- NO_FLAGS = 0,
-
- // If set, calculate and print the difference between successive trace messages.
- INCLUDE_TIME_DELTAS = 1 << 0,
- // If set, include a 'Metrics' line showing any attached trace metrics.
- INCLUDE_METRICS = 1 << 1,
-
- INCLUDE_ALL = INCLUDE_TIME_DELTAS | INCLUDE_METRICS
- };
- void Dump(std::ostream* out, int flags) const;
-
- // Dump the trace buffer as a string.
- std::string DumpToString(int flags = INCLUDE_ALL) const;
-
- std::string MetricsAsJSON() const;
-
- // Attaches the given trace which will get appended at the end when Dumping.
- //
- // The 'label' does not necessarily have to be unique, and is used to identify
- // the child trace when dumped. The contents of the StringPiece are copied
- // into this trace's arena.
- void AddChildTrace(StringPiece label, Trace* child_trace);
-
- // Return a copy of the current set of related "child" traces.
- std::vector<std::pair<StringPiece, scoped_refptr<Trace>>> ChildTraces() const;
-
- // Return the current trace attached to this thread, if there is one.
- static Trace* CurrentTrace() { return threadlocal_trace_; }
-
- // Simple function to dump the current trace to stderr, if one is
- // available. This is meant for usage when debugging in gdb via
- // 'call doris::Trace::DumpCurrentTrace();'.
- static void DumpCurrentTrace();
-
- TraceMetrics* metrics() { return &metrics_; }
- const TraceMetrics& metrics() const { return metrics_; }
-
-private:
- friend class ScopedAdoptTrace;
- friend class RefCountedThreadSafe<Trace>;
- ~Trace();
-
- // The current trace for this thread. Threads should only set this using
- // using ScopedAdoptTrace, which handles reference counting the underlying
- // object.
- static __thread Trace* threadlocal_trace_;
-
- // Allocate a new entry from the arena, with enough space to hold a
- // message of length 'len'.
- TraceEntry* NewEntry(int len, const char* file_path, int line_number);
-
- // Add the entry to the linked list of entries.
- void AddEntry(TraceEntry* entry);
-
- void MetricsToJSON(rapidjson::Writer<rapidjson::StringBuffer>* jw) const;
-
- // TODO(yingchun): now we didn't import Arena, instead, we use manual malloc() and free().
- // std::unique_ptr<ThreadSafeArena> arena_;
-
- // Lock protecting the entries linked list.
- mutable SpinLock lock_;
- // The head of the linked list of entries (allocated inside arena_)
- TraceEntry* entries_head_;
- // The tail of the linked list of entries (allocated inside arena_)
- TraceEntry* entries_tail_;
-
- std::vector<std::pair<StringPiece, scoped_refptr<Trace>>> child_traces_;
-
- TraceMetrics metrics_;
-
- DISALLOW_COPY_AND_ASSIGN(Trace);
-};
-
-// Adopt a Trace object into the current thread for the duration
-// of this object.
-// This should only be used on the stack (and thus created and destroyed
-// on the same thread)
-class ScopedAdoptTrace {
-public:
- explicit ScopedAdoptTrace(Trace* t) : old_trace_(Trace::threadlocal_trace_) {
- Trace::threadlocal_trace_ = t;
- if (t) {
- t->AddRef();
- }
- DFAKE_SCOPED_LOCK_THREAD_LOCKED(ctor_dtor_);
- }
-
- ~ScopedAdoptTrace() {
- if (Trace::threadlocal_trace_) {
- Trace::threadlocal_trace_->Release();
- }
- Trace::threadlocal_trace_ = old_trace_;
- DFAKE_SCOPED_LOCK_THREAD_LOCKED(ctor_dtor_);
- }
-
-private:
- DFAKE_MUTEX(ctor_dtor_);
- Trace* old_trace_;
-
- DISALLOW_COPY_AND_ASSIGN(ScopedAdoptTrace);
-};
-
-// Implementation for TRACE_COUNTER_SCOPE_LATENCY_US(...) macro above.
-class ScopedTraceLatencyCounter {
-public:
- explicit ScopedTraceLatencyCounter(const char* counter)
- : counter_(counter), start_time_(GetCurrentTimeMicros()) {}
-
- ~ScopedTraceLatencyCounter() {
- TRACE_COUNTER_INCREMENT(counter_, GetCurrentTimeMicros() - start_time_);
- }
-
-private:
- const char* const counter_;
- int64_t start_time_;
- DISALLOW_COPY_AND_ASSIGN(ScopedTraceLatencyCounter);
-};
-
-} // namespace doris
diff --git a/be/src/util/trace_metrics.cpp b/be/src/util/trace_metrics.cpp
deleted file mode 100644
index 4b876847bd..0000000000
--- a/be/src/util/trace_metrics.cpp
+++ /dev/null
@@ -1,70 +0,0 @@
-// Licensed to the Apache Software Foundation (ASF) under one
-// or more contributor license agreements. See the NOTICE file
-// distributed with this work for additional information
-// regarding copyright ownership. The ASF licenses this file
-// to you under the Apache License, Version 2.0 (the
-// "License"); you may not use this file except in compliance
-// with the License. You may obtain a copy of the License at
-//
-// http://www.apache.org/licenses/LICENSE-2.0
-//
-// Unless required by applicable law or agreed to in writing,
-// software distributed under the License is distributed on an
-// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
-// KIND, either express or implied. See the License for the
-// specific language governing permissions and limitations
-// under the License.
-
-#include "util/trace_metrics.h"
-
-#include <glog/logging.h>
-#include <glog/stl_logging.h>
-
-#include <algorithm>
-#include <cctype>
-#include <cstring>
-#include <map>
-#include <mutex>
-#include <ostream>
-#include <string>
-#include <utility>
-
-#include "util/debug/leakcheck_disabler.h"
-
-using std::string;
-
-namespace doris {
-
-namespace {
-
-static SpinLock g_intern_map_lock;
-typedef std::map<string, const char*> InternMap;
-static InternMap* g_intern_map;
-
-} // anonymous namespace
-
-const char* TraceMetrics::InternName(const string& name) {
- DCHECK(std::all_of(name.begin(), name.end(), [](char c) { return isprint(c); }))
- << "not printable: " << name;
-
- debug::ScopedLeakCheckDisabler no_leakcheck;
- std::lock_guard<SpinLock> l(g_intern_map_lock);
- if (g_intern_map == nullptr) {
- g_intern_map = new InternMap();
- }
-
- InternMap::iterator it = g_intern_map->find(name);
- if (it != g_intern_map->end()) {
- return it->second;
- }
-
- const char* dup = strdup(name.c_str());
- (*g_intern_map)[name] = dup;
-
- // We don't expect this map to grow large.
- DCHECK_LT(g_intern_map->size(), 100) << "Too many interned strings: " << *g_intern_map;
-
- return dup;
-}
-
-} // namespace doris
diff --git a/be/src/util/trace_metrics.h b/be/src/util/trace_metrics.h
deleted file mode 100644
index 37f43b5924..0000000000
--- a/be/src/util/trace_metrics.h
+++ /dev/null
@@ -1,90 +0,0 @@
-// Licensed to the Apache Software Foundation (ASF) under one
-// or more contributor license agreements. See the NOTICE file
-// distributed with this work for additional information
-// regarding copyright ownership. The ASF licenses this file
-// to you under the Apache License, Version 2.0 (the
-// "License"); you may not use this file except in compliance
-// with the License. You may obtain a copy of the License at
-//
-// http://www.apache.org/licenses/LICENSE-2.0
-//
-// Unless required by applicable law or agreed to in writing,
-// software distributed under the License is distributed on an
-// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
-// KIND, either express or implied. See the License for the
-// specific language governing permissions and limitations
-// under the License.
-#pragma once
-
-#include <butil/macros.h>
-
-#include <cstdint>
-#include <map>
-#include <mutex>
-#include <string>
-
-#include "gutil/map-util.h"
-#include "util/spinlock.h"
-
-namespace doris {
-
-// A simple map of constant string names to integer counters.
-//
-// Typically, the TRACE_COUNTER_INCREMENT(...) macro defined in
-// trace.h is used to increment a counter within this map.
-//
-// This currently is just a thin wrapper around a spinlocked map,
-// but if it becomes noticeable in the CPU profile, various optimizations
-// are plausible.
-class TraceMetrics {
-public:
- TraceMetrics() {}
- ~TraceMetrics() {}
-
- // Internalize the given string by duplicating it into a process-wide
- // pool. If this string has already been interned, returns a pointer
- // to a previous instance. Otherwise, copies it into the pool.
- //
- // The resulting strings are purposefully leaked, so this should only
- // be used in cases where the number of unique strings that will be
- // passed is relatively low (i.e. not user-specified).
- //
- // Because 'name' is exposed back to operators, it must be a printable
- // ASCII string.
- static const char* InternName(const std::string& name);
-
- // Increment the given counter.
- void Increment(const char* name, int64_t amount);
-
- // Return a copy of the current counter map.
- std::map<const char*, int64_t> Get() const;
-
- // Return metric's current value.
- //
- // NOTE: the 'name' MUST be the same const char* which is used for
- // insertion. This is because we do pointer-wise comparison internally.
- int64_t GetMetric(const char* name) const;
-
-private:
- mutable SpinLock lock_;
- std::map<const char*, int64_t> counters_;
-
- DISALLOW_COPY_AND_ASSIGN(TraceMetrics);
-};
-
-inline void TraceMetrics::Increment(const char* name, int64_t amount) {
- std::lock_guard<SpinLock> l(lock_);
- counters_[name] += amount;
-}
-
-inline std::map<const char*, int64_t> TraceMetrics::Get() const {
- std::unique_lock<SpinLock> l(lock_);
- return counters_;
-}
-
-inline int64_t TraceMetrics::GetMetric(const char* name) const {
- std::lock_guard<SpinLock> l(lock_);
- return FindWithDefault(counters_, name, 0);
-}
-
-} // namespace doris
diff --git a/docs/en/docs/admin-manual/config/be-config.md b/docs/en/docs/admin-manual/config/be-config.md
index dbd0435fcd..bd6bc961d7 100644
--- a/docs/en/docs/admin-manual/config/be-config.md
+++ b/docs/en/docs/admin-manual/config/be-config.md
@@ -559,7 +559,18 @@ There are two ways to configure BE configuration items:
Base compaction is a long time cost background task, this configuration is the threshold to logging trace information. Trace information in log file looks like:
```
-W0610 11:26:33.804431 56452 storage_engine.cpp:552] Trace:
+W0610 11:26:33.804431 56452 storage_engine.cpp:552] execute base compaction cost 0.00319222
+BaseCompaction:546859:
+ - filtered_rows: 0
+ - input_row_num: 10
+ - input_rowsets_count: 10
+ - input_rowsets_data_size: 2.17 KB
+ - input_segments_num: 10
+ - merge_rowsets_latency: 100000.510ms
+ - merged_rows: 0
+ - output_row_num: 10
+ - output_rowset_data_size: 224.00 B
+ - output_segments_num: 1
0610 11:23:03.727535 (+ 0us) storage_engine.cpp:554] start to perform base compaction
0610 11:23:03.728961 (+ 1426us) storage_engine.cpp:560] found best tablet 546859
0610 11:23:03.728963 (+ 2us) base_compaction.cpp:40] got base compaction lock
@@ -572,7 +583,6 @@ W0610 11:26:33.804431 56452 storage_engine.cpp:552] Trace:
0610 11:26:33.513197 (+ 28715us) compaction.cpp:110] modify rowsets finished
0610 11:26:33.513300 (+ 103us) base_compaction.cpp:49] compaction finished
0610 11:26:33.513441 (+ 141us) base_compaction.cpp:56] unused rowsets have been moved to GC queue
-Metrics: {"filtered_rows":0,"input_row_num":3346807,"input_rowsets_count":42,"input_rowsets_data_size":1256413170,"input_segments_num":44,"merge_rowsets_latency_us":101574444,"merged_rows":0,"output_row_num":3346807,"output_rowset_data_size":1228439659,"output_segments_num":6}
```
#### `cumulative_compaction_trace_threshold`
diff --git a/docs/zh-CN/docs/admin-manual/config/be-config.md b/docs/zh-CN/docs/admin-manual/config/be-config.md
index 8deb99153f..bc4a2cbd1f 100644
--- a/docs/zh-CN/docs/admin-manual/config/be-config.md
+++ b/docs/zh-CN/docs/admin-manual/config/be-config.md
@@ -573,7 +573,18 @@ BE 重启后该配置将失效。如果想持久化修改结果，使用如下
base compaction是一个耗时较长的后台操作，为了跟踪其运行信息，可以调整这个阈值参数来控制trace日志的打印。打印信息如下：
```
-W0610 11:26:33.804431 56452 storage_engine.cpp:552] Trace:
+W0610 11:26:33.804431 56452 storage_engine.cpp:552] execute base compaction cost 0.00319222
+BaseCompaction:546859:
+ - filtered_rows: 0
+ - input_row_num: 10
+ - input_rowsets_count: 10
+ - input_rowsets_data_size: 2.17 KB
+ - input_segments_num: 10
+ - merge_rowsets_latency: 100000.510ms
+ - merged_rows: 0
+ - output_row_num: 10
+ - output_rowset_data_size: 224.00 B
+ - output_segments_num: 1
0610 11:23:03.727535 (+ 0us) storage_engine.cpp:554] start to perform base compaction
0610 11:23:03.728961 (+ 1426us) storage_engine.cpp:560] found best tablet 546859
0610 11:23:03.728963 (+ 2us) base_compaction.cpp:40] got base compaction lock
@@ -586,7 +597,6 @@ W0610 11:26:33.804431 56452 storage_engine.cpp:552] Trace:
0610 11:26:33.513197 (+ 28715us) compaction.cpp:110] modify rowsets finished
0610 11:26:33.513300 (+ 103us) base_compaction.cpp:49] compaction finished
0610 11:26:33.513441 (+ 141us) base_compaction.cpp:56] unused rowsets have been moved to GC queue
-Metrics: {"filtered_rows":0,"input_row_num":3346807,"input_rowsets_count":42,"input_rowsets_data_size":1256413170,"input_segments_num":44,"merge_rowsets_latency_us":101574444,"merged_rows":0,"output_row_num":3346807,"output_rowset_data_size":1228439659,"output_segments_num":6}
```
#### `cumulative_compaction_trace_threshold`
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org