分析Q16执行耗时究竟在哪里
分析:
火焰图：
分析:
- 占用时间的大头在物化中的aggregate
日志埋点:
[2022-08-09 21:58:35.661551] [61425] [INFO] [temp_table.cpp:2043] MSG: Timer 0.006423 : TempTable::Materialize over
[2022-08-09 21:58:40.601132] [61425] [INFO] [aggregation_algorithm.cpp:75] MSG: AggregationAlgorithm [AggregationAlgorithm::Aggregate start] memLeft: 250803432
[2022-08-09 21:59:02.272033] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 4.776923 : MultiDimensionalDistinctScan index: 7422784
[2022-08-09 21:59:06.900646] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 4.618125 : MultiDimensionalDistinctScan index: 7118920
[2022-08-09 21:59:11.049991] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 4.138833 : MultiDimensionalDistinctScan index: 6388664
[2022-08-09 21:59:14.729436] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 3.668982 : MultiDimensionalDistinctScan index: 5536700
[2022-08-09 21:59:18.003550] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 3.263696 : MultiDimensionalDistinctScan index: 4867184
[2022-08-09 21:59:20.815750] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 2.801977 : MultiDimensionalDistinctScan index: 4077864
[2022-08-09 21:59:23.193645] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 2.367468 : MultiDimensionalDistinctScan index: 3287136
[2022-08-09 21:59:25.129056] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 1.924884 : MultiDimensionalDistinctScan index: 2558128
[2022-08-09 21:59:26.635697] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 1.496256 : MultiDimensionalDistinctScan index: 1828284
[2022-08-09 21:59:27.625411] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 0.979455 : MultiDimensionalDistinctScan index: 916828
[2022-08-09 21:59:28.247990] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 0.611987 : MultiDimensionalDistinctScan index: 243348
[2022-08-09 21:59:46.427592] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 4.695173 : MultiDimensionalDistinctScan index: 7301112
[2022-08-09 21:59:50.880305] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 4.442508 : MultiDimensionalDistinctScan index: 6936244
[2022-08-09 21:59:54.887755] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 3.997080 : MultiDimensionalDistinctScan index: 6145216
[2022-08-09 21:59:58.459334] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 3.561216 : MultiDimensionalDistinctScan index: 5354064
[2022-08-09 22:00:01.555317] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 3.085863 : MultiDimensionalDistinctScan index: 4563312
[2022-08-09 22:00:04.354050] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 2.788534 : MultiDimensionalDistinctScan index: 3895536
[2022-08-09 22:00:06.712467] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 2.347400 : MultiDimensionalDistinctScan index: 3165648
[2022-08-09 22:00:08.510846] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 1.787973 : MultiDimensionalDistinctScan index: 2315076
[2022-08-09 22:00:09.853298] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 1.331898 : MultiDimensionalDistinctScan index: 1524584
[2022-08-09 22:00:10.709280] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 0.845440 : MultiDimensionalDistinctScan index: 673088
[2022-08-09 22:00:23.493576] [61196] [INFO] [engine.cpp:1352] MSG: Command: select 4/4, update 0/0, insert 0/0, load 0/0, queries 0/11
[2022-08-09 22:00:23.493703] [61196] [INFO] [engine.cpp:1364] MSG: Select: 0/1, Loaded: 0/0(0/0), dup: 0/0, insert: 0/0, failed insert: 0/0, update: 0/0
[2022-08-09 22:00:26.931971] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 4.573716 : MultiDimensionalDistinctScan index: 7118920
[2022-08-09 22:00:31.343835] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 4.401538 : MultiDimensionalDistinctScan index: 6875492
[2022-08-09 22:00:35.261567] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 3.907601 : MultiDimensionalDistinctScan index: 6023624
[2022-08-09 22:00:38.722789] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 3.450872 : MultiDimensionalDistinctScan index: 5232348
[2022-08-09 22:00:41.677207] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 2.942256 : MultiDimensionalDistinctScan index: 4320688
[2022-08-09 22:00:44.200292] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 2.512840 : MultiDimensionalDistinctScan index: 3591280
[2022-08-09 22:00:46.202083] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 1.991442 : MultiDimensionalDistinctScan index: 2679604
[2022-08-09 22:00:47.783475] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 1.571247 : MultiDimensionalDistinctScan index: 1949916
[2022-08-09 22:00:48.879044] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 1.085403 : MultiDimensionalDistinctScan index: 1099112
[2022-08-09 22:00:49.574514] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 0.685280 : MultiDimensionalDistinctScan index: 369464
[2022-08-09 22:01:03.876123] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 4.413452 : MultiDimensionalDistinctScan index: 6875492
[2022-08-09 22:01:08.099446] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 4.213053 : MultiDimensionalDistinctScan index: 6571080
[2022-08-09 22:01:11.822763] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 3.712914 : MultiDimensionalDistinctScan index: 5658540
[2022-08-09 22:01:15.064234] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 3.231342 : MultiDimensionalDistinctScan index: 4867320
[2022-08-09 22:01:17.856746] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 2.782235 : MultiDimensionalDistinctScan index: 4077708
[2022-08-09 22:01:20.225255] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 2.358306 : MultiDimensionalDistinctScan index: 3348056
[2022-08-09 22:01:22.078699] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 1.842210 : MultiDimensionalDistinctScan index: 2436356
[2022-08-09 22:01:23.378127] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 1.289039 : MultiDimensionalDistinctScan index: 1463748
[2022-08-09 22:01:23.494066] [61196] [INFO] [engine.cpp:1352] MSG: Command: select 5/9, update 0/0, insert 0/0, load 0/0, queries 12/23
[2022-08-09 22:01:23.494132] [61196] [INFO] [engine.cpp:1364] MSG: Select: 0/1, Loaded: 0/0(0/0), dup: 0/0, insert: 0/0, failed insert: 0/0, update: 0/0
[2022-08-09 22:01:24.266861] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 0.877328 : MultiDimensionalDistinctScan index: 733792
[2022-08-09 22:01:36.696847] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 4.241217 : MultiDimensionalDistinctScan index: 6632096
[2022-08-09 22:01:40.624744] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 3.917591 : MultiDimensionalDistinctScan index: 6084336
[2022-08-09 22:01:44.073692] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 3.438733 : MultiDimensionalDistinctScan index: 5232348
[2022-08-09 22:01:47.027979] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 2.943680 : MultiDimensionalDistinctScan index: 4381292
[2022-08-09 22:01:49.461790] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 2.423435 : MultiDimensionalDistinctScan index: 3469804
[2022-08-09 22:01:51.416958] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 1.944651 : MultiDimensionalDistinctScan index: 2619084
[2022-08-09 22:01:52.851393] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 1.423935 : MultiDimensionalDistinctScan index: 1706776
[2022-08-09 22:01:53.770386] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 0.908534 : MultiDimensionalDistinctScan index: 794732
[2022-08-09 22:02:04.250603] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 3.988361 : MultiDimensionalDistinctScan index: 6266932
[2022-08-09 22:02:07.795016] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 3.534161 : MultiDimensionalDistinctScan index: 5475808
[2022-08-09 22:02:10.759909] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 2.954689 : MultiDimensionalDistinctScan index: 4441772
[2022-08-09 22:02:13.189040] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 2.418797 : MultiDimensionalDistinctScan index: 3469804
[2022-08-09 22:02:15.051540] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 1.852128 : MultiDimensionalDistinctScan index: 2497300
[2022-08-09 22:02:16.336874] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 1.274991 : MultiDimensionalDistinctScan index: 1463748
[2022-08-09 22:02:17.061614] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 0.714381 : MultiDimensionalDistinctScan index: 430320
[2022-08-09 22:02:23.494450] [61196] [INFO] [engine.cpp:1352] MSG: Command: select 0/9, update 0/0, insert 0/0, load 0/0, queries 0/23
[2022-08-09 22:02:23.494525] [61196] [INFO] [engine.cpp:1364] MSG: Select: 0/1, Loaded: 0/0(0/0), dup: 0/0, insert: 0/0, failed insert: 0/0, update: 0/0
[2022-08-09 22:02:25.310746] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 3.435298 : MultiDimensionalDistinctScan index: 5414948
[2022-08-09 22:02:28.054595] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 2.733469 : MultiDimensionalDistinctScan index: 4138488
[2022-08-09 22:02:29.924268] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 1.859229 : MultiDimensionalDistinctScan index: 2558256
[2022-08-09 22:02:30.934135] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 0.999507 : MultiDimensionalDistinctScan index: 977548
[2022-08-09 22:02:35.003509] [61425] [INFO] [aggregation_algorithm.cpp:539] MSG: Timer 0.957001 : MultiDimensionalDistinctScan index: 912740
[2022-08-09 22:02:35.009082] [61425] [INFO] [aggregation_algorithm.cpp:253] MSG: Timer 234.252762 : AggregationAlgorithm::Aggregate MultiDimensionalGroupByScan
[2022-08-09 22:02:35.009615] [61425] [INFO] [aggregation_algorithm.cpp:267] MSG: Timer 234.408798 : AggregationAlgorithm::Aggregate over aggregate_time: 234.408798
[2022-08-09 22:02:35.009875] [61425] [INFO] [aggregation_algorithm.cpp:75] MSG: AggregationAlgorithm [AggregationAlgorithm::Aggregate over] memLeft: 250378324
[2022-08-09 22:02:36.327052] [61425] [INFO] [temp_table.cpp:2043] MSG: Timer 235.726242 : TempTable::Materialize over
核心函数:
AggregationAlgorithm::MultiDimensionalDistinctScan
void AggregationAlgorithm::MultiDimensionalDistinctScan(GroupByWrapper &gbw, MIIterator &mit) {
// NOTE: to maintain distinct cache compatibility, rows must be visited in the
// same order!
MEASURE_FET("TempTable::MultiDimensionalDistinctScan(GroupByWrapper& gbw)");
while (gbw.AnyOmittedByDistinct()) { // any distincts omitted? =>
// another pass needed
// Some displays
int64_t max_size_for_display = 0;
for (int i = gbw.NumOfGroupingAttrs(); i < gbw.NumOfAttrs(); i++)
if (gbw.distinct_watch.OmittedFilter(i) && gbw.distinct_watch.OmittedFilter(i)->NumOfOnes() > max_size_for_display)
max_size_for_display = gbw.distinct_watch.OmittedFilter(i)->NumOfOnes();
rccontrol.lock(m_conn->GetThreadID())
<< "Next distinct pass: " << max_size_for_display << " rows left" << system::unlock;
gbw.RewindDistinctBuffers(); // reset buffers for a new contents, rewind
// cache
std::chrono::high_resolution_clock::time_point outer_start = std::chrono::high_resolution_clock::now();
for (int distinct_attr = gbw.NumOfGroupingAttrs(); distinct_attr < gbw.NumOfAttrs(); distinct_attr++) {
Filter *omit_filter = gbw.distinct_watch.OmittedFilter(distinct_attr);
if (omit_filter && !omit_filter->IsEmpty()) {
mit.Rewind();
int64_t cur_tuple = 0;
int64_t uniform_pos = common::NULL_VALUE_64;
bool require_locking = true;
std::chrono::high_resolution_clock::time_point start = std::chrono::high_resolution_clock::now();
int index = 0;
while (mit.IsValid()) {
if (mit.PackrowStarted()) {
if (m_conn->Killed()) throw common::KilledException();
// All packrow-level operations
omit_filter->Commit();
gbw.ResetPackrow();
bool skip_packrow = false;
bool packrow_done = false;
bool part_omitted = false;
bool stop_all = false;
int64_t packrow_length = mit.GetPackSizeLeft();
// Check whether the packrow contain any not aggregated rows
if (omit_filter->IsEmptyBetween(cur_tuple, cur_tuple + packrow_length - 1))
skip_packrow = true;
else {
int64_t rows_in_pack = omit_filter->NumOfOnesBetween(cur_tuple, cur_tuple + packrow_length - 1);
bool agg_not_changeable = false;
AggregateRough(gbw, mit, packrow_done, part_omitted, agg_not_changeable, stop_all, uniform_pos,
rows_in_pack, 1, distinct_attr);
if (packrow_done) { // This packrow will not be needed any more
omit_filter->ResetBetween(cur_tuple, cur_tuple + packrow_length - 1);
gbw.OmitInCache(distinct_attr, packrow_length);
}
}
if (skip_packrow) {
mit.NextPackrow();
cur_tuple += packrow_length;
continue;
}
require_locking = true; // a new packrow, so locking will be needed
}
// All row-level operations
if (omit_filter->Get(cur_tuple)) {
bool value_successfully_aggregated = false;
if (gbw.CacheValid(distinct_attr)) {
value_successfully_aggregated = gbw.PutCachedValue(distinct_attr);
} else {
// Locking etc.
if (require_locking) {
gbw.LockPack(distinct_attr, mit);
if (uniform_pos != common::PLUS_INF_64)
for (int gr_a = 0; gr_a < gbw.NumOfGroupingAttrs(); gr_a++) gbw.LockPack(gr_a, mit);
require_locking = false;
}
int64_t pos = 0;
bool existed = true;
if (uniform_pos != common::PLUS_INF_64)
pos = uniform_pos; // existed == true, as above
else { // Construct the grouping vector
for (int gr_a = 0; gr_a < gbw.NumOfGroupingAttrs(); gr_a++) {
if (gbw.ColumnNotOmitted(gr_a)) gbw.PutGroupingValue(gr_a, mit);
}
existed = gbw.FindCurrentRow(pos);
}
ASSERT(existed && pos != common::NULL_VALUE_64, "row does not exist");
value_successfully_aggregated = gbw.PutAggregatedValue(distinct_attr, pos, mit);
}
if (value_successfully_aggregated) omit_filter->ResetDelayed(cur_tuple);
gbw.distinct_watch.NextRead(distinct_attr);
}
cur_tuple++;
++mit;
++index;
}
auto diff = std::chrono::duration_cast<std::chrono::duration<float>>(
std::chrono::high_resolution_clock::now() - start);
TIANMU_LOG(LogCtl_Level::INFO, "Timer %f : MultiDimensionalDistinctScan mit index: %d ",
diff.count(), index);
omit_filter->Commit(); // committing delayed resets
}
}
auto outer_diff =
std::chrono::duration_cast<std::chrono::duration<float>>(std::chrono::high_resolution_clock::now() - outer_diff);
TIANMU_LOG(LogCtl_Level::INFO, "Timer %f : MultiDimensionalDistinctScan outer", outer_diff.count());
gbw.UpdateDistinctCaches(); // take into account values already counted
}
}