This is an automated email from the ASF dual-hosted git repository.
lichaoyong pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/incubator-doris.git
The following commit(s) were added to refs/heads/master by this push:
new 3c09e1e [trace] Adapt trace util to compaction module (#3814)
3c09e1e is described below
commit 3c09e1e1d81df23fe252023b58123f4de516807d
Author: Yingchun Lai <[email protected]>
AuthorDate: Sat Jun 13 19:31:51 2020 +0800
[trace] Adapt trace util to compaction module (#3814)
Trace util is helpful for diagnosing compaction performance problems,
we can get trace log for base compaction like:
```
W0610 11:26:33.804431 56452 storage_engine.cpp:552] Trace:
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
0610 11:23:03.729029 (+ 66us) base_compaction.cpp:44] rowsets picked
0610 11:24:51.784439 (+108055410us) compaction.cpp:46] got concurrency lock
and start to do compaction
0610 11:24:51.784818 (+ 379us) compaction.cpp:74] prepare finished
0610 11:26:33.359265 (+101574447us) compaction.cpp:87] merge rowsets
finished
0610 11:26:33.484481 (+125216us) compaction.cpp:102] output rowset built
0610 11:26:33.484482 (+ 1us) compaction.cpp:106] check correctness
finished
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}
```
for cumulative compaction like:
```
W0610 11:14:18.714366 56468 storage_engine.cpp:518] Trace:
0610 11:14:08.068484 (+ 0us) storage_engine.cpp:520] start to perform
cumulative compaction
0610 11:14:08.069844 (+ 1360us) storage_engine.cpp:526] found best tablet
547083
0610 11:14:08.069846 (+ 2us) cumulative_compaction.cpp:42] got
cumulative compaction lock
0610 11:14:08.069947 (+ 101us) cumulative_compaction.cpp:46] calculated
cumulative point
0610 11:14:08.070141 (+ 194us) cumulative_compaction.cpp:50] rowsets
picked
0610 11:14:08.070143 (+ 2us) compaction.cpp:46] got concurrency lock
and start to do compaction
0610 11:14:08.070518 (+ 375us) compaction.cpp:74] prepare finished
0610 11:14:15.389893 (+7319375us) compaction.cpp:87] merge rowsets finished
0610 11:14:15.390916 (+ 1023us) compaction.cpp:102] output rowset built
0610 11:14:15.390917 (+ 1us) compaction.cpp:106] check correctness
finished
0610 11:14:15.409460 (+ 18543us) compaction.cpp:110] modify rowsets finished
0610 11:14:15.409496 (+ 36us) cumulative_compaction.cpp:55] compaction
finished
0610 11:14:15.410138 (+ 642us) cumulative_compaction.cpp:65] unused
rowsets have been moved to GC queue
Metrics:
{"filtered_rows":0,"input_row_num":136707,"input_rowsets_count":302,"input_rowsets_data_size":76617836,"input_segments_num":302,"merge_rowsets_latency_us":7319372,"merged_rows":0,"output_row_num":136707,"output_rowset_data_size":53893280,"output_segments_num":1}
```
---
be/src/common/config.h | 4 +++
be/src/olap/base_compaction.cpp | 6 ++++
be/src/olap/compaction.cpp | 18 +++++++++++-
be/src/olap/cumulative_compaction.cpp | 7 +++++
be/src/olap/merger.cpp | 3 ++
be/src/olap/storage_engine.cpp | 24 +++++++++++++++
docs/en/administrator-guide/config/be_config.md | 33 +++++++++++++++++++++
docs/zh-CN/administrator-guide/config/be_config.md | 34 ++++++++++++++++++++++
8 files changed, 128 insertions(+), 1 deletion(-)
diff --git a/be/src/common/config.h b/be/src/common/config.h
index d48afca..ddb4ede 100644
--- a/be/src/common/config.h
+++ b/be/src/common/config.h
@@ -284,6 +284,10 @@ namespace config {
// This config can be set to 0, which means to forbid any compaction, for
some special cases.
CONF_Int32(max_compaction_concurrency, "-1");
+ // Threshold to logging compaction trace, in seconds.
+ CONF_mInt32(base_compaction_trace_threshold, "10");
+ CONF_mInt32(cumulative_compaction_trace_threshold, "2");
+
// Port to start debug webserver on
CONF_Int32(webserver_port, "8040");
// Number of webserver workers
diff --git a/be/src/olap/base_compaction.cpp b/be/src/olap/base_compaction.cpp
index fe244d9..e65a989 100644
--- a/be/src/olap/base_compaction.cpp
+++ b/be/src/olap/base_compaction.cpp
@@ -17,6 +17,7 @@
#include "olap/base_compaction.h"
#include "util/doris_metrics.h"
+#include "util/trace.h"
namespace doris {
@@ -36,18 +37,23 @@ OLAPStatus BaseCompaction::compact() {
LOG(WARNING) << "another base compaction is running. tablet=" <<
_tablet->full_name();
return OLAP_ERR_BE_TRY_BE_LOCK_ERROR;
}
+ TRACE("got base compaction lock");
// 1. pick rowsets to compact
RETURN_NOT_OK(pick_rowsets_to_compact());
+ TRACE("rowsets picked");
+ TRACE_COUNTER_INCREMENT("input_rowsets_count", _input_rowsets.size());
// 2. do base compaction, merge rowsets
RETURN_NOT_OK(do_compaction());
+ TRACE("compaction finished");
// 3. set state to success
_state = CompactionState::SUCCESS;
// 4. garbage collect input rowsets after base compaction
RETURN_NOT_OK(gc_unused_rowsets());
+ TRACE("unused rowsets have been moved to GC queue");
// 5. add metric to base compaction
DorisMetrics::instance()->base_compaction_deltas_total.increment(_input_rowsets.size());
diff --git a/be/src/olap/compaction.cpp b/be/src/olap/compaction.cpp
index d203b63..adb3b6a 100644
--- a/be/src/olap/compaction.cpp
+++ b/be/src/olap/compaction.cpp
@@ -19,6 +19,7 @@
#include "olap/compaction.h"
#include "olap/rowset/rowset_factory.h"
#include "util/time.h"
+#include "util/trace.h"
using std::vector;
@@ -42,6 +43,7 @@ OLAPStatus Compaction::init(int concurreny) {
OLAPStatus Compaction::do_compaction() {
_concurrency_sem.wait();
+ TRACE("got concurrency lock and start to do compaction");
OLAPStatus st = do_compaction_impl();
_concurrency_sem.signal();
return st;
@@ -57,6 +59,10 @@ OLAPStatus Compaction::do_compaction_impl() {
_input_row_num += rowset->num_rows();
segments_num += 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", segments_num);
+
_output_version = Version(_input_rowsets.front()->start_version(),
_input_rowsets.back()->end_version());
_tablet->compute_version_hash_from_rowsets(_input_rowsets,
&_output_version_hash);
@@ -65,6 +71,7 @@ OLAPStatus Compaction::do_compaction_impl() {
RETURN_NOT_OK(construct_output_rowset_writer());
RETURN_NOT_OK(construct_input_rowset_readers());
+ TRACE("prepare finished");
// 2. write merged rows to output rowset
Merger::Statistics stats;
@@ -77,6 +84,9 @@ OLAPStatus Compaction::do_compaction_impl() {
<< "-" << _output_version.second;
return res;
}
+ TRACE("merge rowsets finished");
+ TRACE_COUNTER_INCREMENT("merged_rows", stats.merged_rows);
+ TRACE_COUNTER_INCREMENT("filtered_rows", stats.filtered_rows);
_output_rowset = _output_rs_writer->build();
if (_output_rowset == nullptr) {
@@ -85,12 +95,18 @@ OLAPStatus Compaction::do_compaction_impl() {
<< "-" << _output_version.second;
return OLAP_ERR_MALLOC_ERROR;
}
+ 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());
+ TRACE("output rowset built");
// 3. check correctness
RETURN_NOT_OK(check_correctness(stats));
+ TRACE("check correctness finished");
// 4. modify rowsets in memory
modify_rowsets();
+ TRACE("modify rowsets finished");
// 5. update last success compaction time
int64_t now = UnixMillis();
@@ -98,7 +114,7 @@ OLAPStatus Compaction::do_compaction_impl() {
_tablet->set_last_cumu_compaction_success_time(now);
} else {
_tablet->set_last_base_compaction_success_time(now);
- }
+ }
LOG(INFO) << "succeed to do " << compaction_name()
<< ". tablet=" << _tablet->full_name()
diff --git a/be/src/olap/cumulative_compaction.cpp
b/be/src/olap/cumulative_compaction.cpp
index a96e8f4..f0a6bf2 100755
--- a/be/src/olap/cumulative_compaction.cpp
+++ b/be/src/olap/cumulative_compaction.cpp
@@ -18,6 +18,7 @@
#include "olap/cumulative_compaction.h"
#include "util/doris_metrics.h"
#include "util/time.h"
+#include "util/trace.h"
namespace doris {
@@ -38,15 +39,20 @@ OLAPStatus CumulativeCompaction::compact() {
LOG(INFO) << "The tablet is under cumulative compaction. tablet=" <<
_tablet->full_name();
return OLAP_ERR_CE_TRY_CE_LOCK_ERROR;
}
+ TRACE("got cumulative compaction lock");
// 1.calculate cumulative point
_tablet->calculate_cumulative_point();
+ TRACE("calculated cumulative point");
// 2. pick rowsets to compact
RETURN_NOT_OK(pick_rowsets_to_compact());
+ TRACE("rowsets picked");
+ TRACE_COUNTER_INCREMENT("input_rowsets_count", _input_rowsets.size());
// 3. do cumulative compaction, merge rowsets
RETURN_NOT_OK(do_compaction());
+ TRACE("compaction finished");
// 4. set state to success
_state = CompactionState::SUCCESS;
@@ -56,6 +62,7 @@ OLAPStatus CumulativeCompaction::compact() {
// 6. garbage collect input rowsets after cumulative compaction
RETURN_NOT_OK(gc_unused_rowsets());
+ TRACE("unused rowsets have been moved to GC queue");
// 7. add metric to cumulative compaction
DorisMetrics::instance()->cumulative_compaction_deltas_total.increment(_input_rowsets.size());
diff --git a/be/src/olap/merger.cpp b/be/src/olap/merger.cpp
index d46f4b0..e6e6e1b 100644
--- a/be/src/olap/merger.cpp
+++ b/be/src/olap/merger.cpp
@@ -24,6 +24,7 @@
#include "olap/tablet.h"
#include "olap/reader.h"
#include "olap/row_cursor.h"
+#include "util/trace.h"
namespace doris {
@@ -32,6 +33,8 @@ OLAPStatus Merger::merge_rowsets(TabletSharedPtr tablet,
const std::vector<RowsetReaderSharedPtr>&
src_rowset_readers,
RowsetWriter* dst_rowset_writer,
Merger::Statistics* stats_output) {
+ TRACE_COUNTER_SCOPE_LATENCY_US("merge_rowsets_latency_us");
+
Reader reader;
ReaderParams reader_params;
reader_params.tablet = tablet;
diff --git a/be/src/olap/storage_engine.cpp b/be/src/olap/storage_engine.cpp
index c7b433f..61d7ab9 100644
--- a/be/src/olap/storage_engine.cpp
+++ b/be/src/olap/storage_engine.cpp
@@ -53,9 +53,11 @@
#include "olap/rowset/unique_rowset_id_generator.h"
#include "olap/fs/file_block_manager.h"
#include "util/time.h"
+#include "util/trace.h"
#include "util/doris_metrics.h"
#include "util/pretty_printer.h"
#include "util/file_utils.h"
+#include "util/scoped_cleanup.h"
#include "agent/cgroups_mgr.h"
using apache::thrift::ThriftDebugString;
@@ -506,11 +508,22 @@ void StorageEngine::_start_clean_fd_cache() {
}
void StorageEngine::_perform_cumulative_compaction(DataDir* data_dir) {
+ 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);
+ }
+ });
+ ADOPT_TRACE(trace.get());
+ TRACE("start to perform cumulative compaction");
TabletSharedPtr best_tablet =
_tablet_manager->find_best_tablet_to_compaction(
CompactionType::CUMULATIVE_COMPACTION, data_dir);
if (best_tablet == nullptr) {
return;
}
+ TRACE("found best tablet $0", best_tablet->get_tablet_info().tablet_id);
DorisMetrics::instance()->cumulative_compaction_request_total.increment(1);
CumulativeCompaction cumulative_compaction(best_tablet);
@@ -529,11 +542,22 @@ void
StorageEngine::_perform_cumulative_compaction(DataDir* data_dir) {
}
void StorageEngine::_perform_base_compaction(DataDir* data_dir) {
+ 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);
+ }
+ });
+ ADOPT_TRACE(trace.get());
+ TRACE("start to perform base compaction");
TabletSharedPtr best_tablet =
_tablet_manager->find_best_tablet_to_compaction(
CompactionType::BASE_COMPACTION, data_dir);
if (best_tablet == nullptr) {
return;
}
+ TRACE("found best tablet $0", best_tablet->get_tablet_info().tablet_id);
DorisMetrics::instance()->base_compaction_request_total.increment(1);
BaseCompaction base_compaction(best_tablet);
diff --git a/docs/en/administrator-guide/config/be_config.md
b/docs/en/administrator-guide/config/be_config.md
index 22790a5..ae4cf45 100644
--- a/docs/en/administrator-guide/config/be_config.md
+++ b/docs/en/administrator-guide/config/be_config.md
@@ -51,6 +51,31 @@ This document mainly introduces the relevant configuration
items of BE.
### `base_compaction_num_threads_per_disk`
+### base_compaction_trace_threshold
+
+* Type: int32
+* Description: Threshold to logging base compaction's trace information, in
seconds
+* Default value: 10
+
+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:
+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
+0610 11:23:03.729029 (+ 66us) base_compaction.cpp:44] rowsets picked
+0610 11:24:51.784439 (+108055410us) compaction.cpp:46] got concurrency lock
and start to do compaction
+0610 11:24:51.784818 (+ 379us) compaction.cpp:74] prepare finished
+0610 11:26:33.359265 (+101574447us) compaction.cpp:87] merge rowsets finished
+0610 11:26:33.484481 (+125216us) compaction.cpp:102] output rowset built
+0610 11:26:33.484482 (+ 1us) compaction.cpp:106] check correctness finished
+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}
+```
+
### `base_compaction_write_mbytes_per_sec`
### `base_cumulative_delta_ratio`
@@ -115,6 +140,14 @@ User can set this configuration to a larger value to get
better QPS performance.
### `cumulative_compaction_skip_window_seconds`
+### cumulative_compaction_trace_threshold
+
+* Type: int32
+* Description: Threshold to logging cumulative compaction's trace information,
in seconds
+* Default value: 10
+
+Similar to `base_compaction_trace_threshold`.
+
### `default_num_rows_per_column_file_block`
### `default_query_options`
diff --git a/docs/zh-CN/administrator-guide/config/be_config.md
b/docs/zh-CN/administrator-guide/config/be_config.md
index 5a90d70..de57375 100644
--- a/docs/zh-CN/administrator-guide/config/be_config.md
+++ b/docs/zh-CN/administrator-guide/config/be_config.md
@@ -459,3 +459,37 @@ load tablets from header failed, failed tablets size: xxx,
path=xxx
1. tablet 信息不可修复，在确保其他副本正常的情况下，可以通过 `meta_tool` 工具将错误的tablet删除。
2. 将 `ignore_load_tablet_failure` 设置为 true，则 BE 会忽略这些错误的 tablet，正常启动。
+
+### base_compaction_trace_threshold
+
+* 类型：int32
+* 描述：打印base compaction的trace信息的阈值，单位秒
+* 默认值：10
+
+base compaction是一个耗时较长的后台操作，为了跟踪其运行信息，可以调整这个阈值参数来控制trace日志的打印。打印信息如下：
+
+```
+W0610 11:26:33.804431 56452 storage_engine.cpp:552] Trace:
+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
+0610 11:23:03.729029 (+ 66us) base_compaction.cpp:44] rowsets picked
+0610 11:24:51.784439 (+108055410us) compaction.cpp:46] got concurrency lock
and start to do compaction
+0610 11:24:51.784818 (+ 379us) compaction.cpp:74] prepare finished
+0610 11:26:33.359265 (+101574447us) compaction.cpp:87] merge rowsets finished
+0610 11:26:33.484481 (+125216us) compaction.cpp:102] output rowset built
+0610 11:26:33.484482 (+ 1us) compaction.cpp:106] check correctness finished
+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
+
+* 类型：int32
+* 描述：打印cumulative compaction的trace信息的阈值，单位秒
+* 默认值：2
+
+与base_compaction_trace_threshold类似。
+
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
