当前位置：网站首页>2022-08-10 mysql/stonedb-慢SQL-Q16-耗时追踪
2022-08-10 mysql/stonedb-慢SQL-Q16-耗时追踪
2022-08-11 06:50:00 【帝尊悟世】
摘要:
分析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
}
}边栏推荐
- SQL sliding window
- NTT的Another Me技术助力创造歌舞伎演员中村狮童的数字孪生体，将在 “Cho Kabuki 2022 Powered by NTT”舞台剧中首次亮相
- DDR4内存条电路设计
- 1056 组合数的和 (15 分)
- Redis源码-String：Redis String命令、Redis String存储原理、Redis字符串三种编码类型、Redis String SDS源码解析、Redis String应用场景
- 1081 检查密码 (15 分)
- Unity程序员如何提升自己的能力
- 联想集团：2022/23财年第一季度业绩
- 博途PLC 1200/1500PLC ModbusTcp通信梯形图优化汇总（多服务器多从站轮询）
- 无服务器+域名也能搭建个人博客?真的,而且很快
猜你喜欢
opencv实现数据增强（图片+标签）平移，翻转，缩放，旋转
【latex异常和错误】Missing $ inserted.＜inserted text＞You can‘t use \spacefactor in math mode.输出文本要注意特殊字符的转义
TF中使用softmax函数；
Implementation of FIR filter based on FPGA (5) - FPGA code implementation of parallel structure FIR filter
NFT 的价值从何而来
A used in the study of EEG ultra scanning analysis process
TF中的One-hot
接口测试的基础流程和用例设计方法你知道吗？
buu—Re（5）
【LaTex-错误和异常】\verb ended by end of line.原因是因为闭合边界符没有在\verb命令所属行中出现；\verb命令的正确和错误用法、verbatim环境的用法
随机推荐
golang fork 进程的三种方式
Edge provides label grouping functionality
深度监督（中继监督）
break pad源码编译--参考大佬博客的总结
计算YUV文件的PSNR与SSIM
1096 大美数 (15 分)
Activity的四种启动模式
2021-08-11 for循环结合多线程异步查询并收集结果
LeetCode刷题系列 -- 46. 全排列
Unity程序员如何提升自己的能力
Taobao product details API interface
【LeetCode每日一题】——844.比较含退格的字符串
无服务器+域名也能搭建个人博客?真的,而且很快
Implementation of FIR filter based on FPGA (5) - FPGA code implementation of parallel structure FIR filter
PIXHAWK飞控使用RTK
【latex异常和错误】Missing $ inserted.＜inserted text＞You can‘t use \spacefactor in math mode.输出文本要注意特殊字符的转义
1036 跟奥巴马一起编程 (15 分)
伦敦银规则有哪些?
How to choose professional, safe and high-performance remote control software
Unity底层是如何处理C＃的