共计 45908 个字符,预计需要花费 115 分钟才能阅读完成。
摘要:
子查问耗时 40 分钟,通过火焰图剖析发现 memcpy 占用了大量工夫,剖析其起因
子查问调用剖析:
火焰图:
https://gitee.com/adofsuaron/stonedb-dev/blob/stonedb-5.6/tests/perf/vm-30.208/subquery-slow-20220711Jul071657525409.mysql.svg
函数调用计数统计:
OP 类型都是 EXISTS
[2022-07-15 12:44:24.190555] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 13.609516 : EvaluatePackImpl: midCheckNum : 2419 opExistNum: 2419 opOther : 0
[2022-07-15 12:44:36.104496] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 11.905251 : EvaluatePackImpl: midCheckNum : 2395 opExistNum: 2395 opOther : 0
[2022-07-15 12:44:47.915683] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 11.800246 : EvaluatePackImpl: midCheckNum : 2432 opExistNum: 2432 opOther : 0
[2022-07-15 12:45:01.263916] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 13.341514 : EvaluatePackImpl: midCheckNum : 2499 opExistNum: 2499 opOther : 0
[2022-07-15 12:45:12.688115] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 11.411891 : EvaluatePackImpl: midCheckNum : 2503 opExistNum: 2503 opOther : 0
[2022-07-15 12:45:22.375204] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 9.674175 : EvaluatePackImpl: midCheckNum : 2531 opExistNum: 2531 opOther : 0
[2022-07-15 12:45:33.026186] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 10.642713 : EvaluatePackImpl: midCheckNum : 2536 opExistNum: 2536 opOther : 0
[2022-07-15 12:45:34.595383] [30234] [INFO] [engine.cpp:1352] MSG: Command: select 6/6, update 0/0, insert 0/0, load 0/0, queries 0/11
[2022-07-15 12:45:34.595527] [30234] [INFO] [engine.cpp:1364] MSG: Select: 0/3, Loaded: 0/0(0/0), dup: 0/0, insert: 0/0, failed insert: 0/0, update: 0/0
[2022-07-15 12:45:47.865536] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 14.825772 : EvaluatePackImpl: midCheckNum : 2529 opExistNum: 2529 opOther : 0
[2022-07-15 12:45:59.249398] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 11.376487 : EvaluatePackImpl: midCheckNum : 2496 opExistNum: 2496 opOther : 0
[2022-07-15 12:46:09.555226] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 10.299180 : EvaluatePackImpl: midCheckNum : 2501 opExistNum: 2501 opOther : 0
[2022-07-15 12:46:19.415523] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 9.852182 : EvaluatePackImpl: midCheckNum : 2582 opExistNum: 2582 opOther : 0
[2022-07-15 12:46:30.799312] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 11.376147 : EvaluatePackImpl: midCheckNum : 2510 opExistNum: 2510 opOther : 0
[2022-07-15 12:46:34.596136] [30234] [INFO] [engine.cpp:1352] MSG: Command: select 0/6, update 0/0, insert 0/0, load 0/0, queries 0/11
[2022-07-15 12:46:34.596240] [30234] [INFO] [engine.cpp:1364] MSG: Select: 0/3, Loaded: 0/0(0/0), dup: 0/0, insert: 0/0, failed insert: 0/0, update: 0/0
[2022-07-15 12:46:44.160092] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 13.354304 : EvaluatePackImpl: midCheckNum : 2530 opExistNum: 2530 opOther : 0
[2022-07-15 12:46:55.629836] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 11.458967 : EvaluatePackImpl: midCheckNum : 2553 opExistNum: 2553 opOther : 0
[2022-07-15 12:47:05.145155] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 9.509394 : EvaluatePackImpl: midCheckNum : 2547 opExistNum: 2547 opOther : 0
[2022-07-15 12:47:17.404713] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 12.253342 : EvaluatePackImpl: midCheckNum : 2481 opExistNum: 2481 opOther : 0
[2022-07-15 12:47:28.987457] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 11.575468 : EvaluatePackImpl: midCheckNum : 2488 opExistNum: 2488 opOther : 0
[2022-07-15 12:47:34.596806] [30234] [INFO] [engine.cpp:1352] MSG: Command: select 0/6, update 0/0, insert 0/0, load 0/0, queries 0/11
[2022-07-15 12:47:34.597060] [30234] [INFO] [engine.cpp:1364] MSG: Select: 0/3, Loaded: 0/0(0/0), dup: 0/0, insert: 0/0, failed insert: 0/0, update: 0/0
[2022-07-15 12:47:40.348232] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 11.354000 : EvaluatePackImpl: midCheckNum : 2485 opExistNum: 2485 opOther : 0
[2022-07-15 12:47:51.732690] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 11.377825 : EvaluatePackImpl: midCheckNum : 2514 opExistNum: 2514 opOther : 0
[2022-07-15 12:48:04.290654] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 12.551874 : EvaluatePackImpl: midCheckNum : 2526 opExistNum: 2526 opOther : 0
[2022-07-15 12:48:13.145068] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 8.847023 : EvaluatePackImpl: midCheckNum : 2414 opExistNum: 2414 opOther : 0
[2022-07-15 12:48:24.899297] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 11.747730 : EvaluatePackImpl: midCheckNum : 2453 opExistNum: 2453 opOther : 0
[2022-07-15 12:48:34.597675] [30234] [INFO] [engine.cpp:1352] MSG: Command: select 0/6, update 0/0, insert 0/0, load 0/0, queries 0/11
[2022-07-15 12:48:34.597795] [30234] [INFO] [engine.cpp:1364] MSG: Select: 0/3, Loaded: 0/0(0/0), dup: 0/0, insert: 0/0, failed insert: 0/0, update: 0/0
[2022-07-15 12:48:34.597829] [30234] [INFO] [engine.cpp:270] MSG: Memory: release [0 3254 0 0] 0, total 0. (un)freeable 1804026329/58024624, total alloc/free 930623689640/928761638687
[2022-07-15 12:48:37.058888] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 12.153567 : EvaluatePackImpl: midCheckNum : 2584 opExistNum: 2584 opOther : 0
[2022-07-15 12:48:49.631277] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 12.565700 : EvaluatePackImpl: midCheckNum : 2567 opExistNum: 2567 opOther : 0
[2022-07-15 12:49:00.402314] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 10.763108 : EvaluatePackImpl: midCheckNum : 2592 opExistNum: 2592 opOther : 0
[2022-07-15 12:49:10.951728] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 10.541731 : EvaluatePackImpl: midCheckNum : 2532 opExistNum: 2532 opOther : 0
[2022-07-15 12:49:23.096156] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 12.135596 : EvaluatePackImpl: midCheckNum : 2536 opExistNum: 2536 opOther : 0
[2022-07-15 12:49:34.248395] [30257] [INFO] [descriptor.cpp:874] MSG: Timer 11.141438 : EvaluatePackImpl: midCheckNum : 2560 opExistNum: 2560 opOther : 0
调用堆栈:
(gdb) bt
#0 stonedb::core::Filter::Block::CopyFrom (this=0x7f614677d000, block=..., owner=0x7f6134e4e430) at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/core/filter_block.cpp:68
#1 0x0000000002d5b7a4 in stonedb::core::Filter::Block::Block (this=0x7f614677d000, block=..., owner=0x7f6134e4e430)
at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/core/filter_block.cpp:52
#2 0x0000000002d53660 in stonedb::core::Filter::Filter (this=0x7f6134e4e430, filter=...) at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/core/filter.cpp:106
#3 0x000000000313582d in stonedb::core::DimensionGroupFilter::DimensionGroupFilter (this=0x7f6134a1d9a0, dim=0, f_source=0x7f61349fda50, copy_mode=0, power=16)
at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/core/dimension_group.cpp:35
#4 0x00000000031387fe in stonedb::core::DimensionGroupFilter::Clone (this=0x7f61349fc930, shallow=false)
at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/core/dimension_group.h:142
#5 0x000000000308f6c0 in stonedb::core::MultiIndex::MultiIndex (this=0x7f6134caa700, s=...) at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/core/multi_index.cpp:54
#6 0x00000000030ac3a0 in stonedb::core::ParameterizedFilter::operator= (this=0x7f61349f1380, pf=...)
at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/core/parameterized_filter.cpp:47
#7 0x0000000002dfdb5c in stonedb::core::TempTableForSubquery::ResetToTemplate (this=0x7f61349f1230, rough=true)
at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/core/temp_table.cpp:2168
#8 0x0000000002ea50e4 in stonedb::vcolumn::SubSelectColumn::RoughPrepareSubqCopy (this=0x7f61349f5810, mit=..., sot=stonedb::core::ROW_BASED)
at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/vc/subselect_column.cpp:403
#9 0x0000000002ea5841 in stonedb::vcolumn::SubSelectColumn::RoughIsEmpty (this=0x7f61349f5810, mit=..., sot=stonedb::core::ROW_BASED)
at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/vc/subselect_column.cpp:487
#10 0x0000000003055ee2 in stonedb::core::Descriptor::RoughCheckSubselectCondition (this=0x7f61349ff2b0, mit=..., sot=stonedb::core::ROW_BASED)
at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/core/descriptor.cpp:1189
#11 0x00000000030527ea in stonedb::core::Descriptor::EvaluatePackImpl (this=0x7f61349ff2b0, mit=...) at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/core/descriptor.cpp:845
#12 0x0000000003052a58 in stonedb::core::Descriptor::EvaluatePack (this=0x7f61349ff2b0, mit=...) at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/core/descriptor.cpp:898
#13 0x00000000030b46de in stonedb::core::ParameterizedFilter::ApplyDescriptor (this=0x7f61349ef110, desc_number=1, limit=-1)
at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/core/parameterized_filter.cpp:1365
#14 0x00000000030b2b37 in stonedb::core::ParameterizedFilter::UpdateMultiIndex (this=0x7f61349ef110, count_only=false, limit=-1)
at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/core/parameterized_filter.cpp:1065
#15 0x0000000002d731f7 in stonedb::core::Query::Preexecute (this=0x7f6501cb2800, qu=..., sender=0x7f61349e6bb0, display_now=true)
at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/core/query.cpp:777
#16 0x0000000002d44a2e in stonedb::core::Engine::Execute (this=0x7779df0, thd=0x7f6134913df0, lex=0x7f6134916118, result_output=0x7f61340091f0, unit_for_union=0x0)
at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/core/engine_execute.cpp:421
#17 0x0000000002d43ce2 in stonedb::core::Engine::HandleSelect (this=0x7779df0, thd=0x7f6134913df0, lex=0x7f6134916118, result=@0x7f6501cb2d18: 0x7f61340091f0, setup_tables_done_option=0,
res=@0x7f6501cb2d14: 0, optimize_after_sdb=@0x7f6501cb2d0c: 1, sdb_free_join=@0x7f6501cb2d10: 1, with_insert=0)
at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/core/engine_execute.cpp:232
#18 0x0000000002e2c4df in stonedb::dbhandler::SDB_HandleSelect (thd=0x7f6134913df0, lex=0x7f6134916118, result=@0x7f6501cb2d18: 0x7f61340091f0, setup_tables_done_option=0, res=@0x7f6501cb2d14: 0,
optimize_after_sdb=@0x7f6501cb2d0c: 1, sdb_free_join=@0x7f6501cb2d10: 1, with_insert=0) at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/stonedb/handler/ha_rcengine.cpp:82
#19 0x000000000246fe5a in execute_sqlcom_select (thd=0x7f6134913df0, all_tables=0x7f6134015440) at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/sql/sql_parse.cc:5182
#20 0x00000000024691de in mysql_execute_command (thd=0x7f6134913df0, first_level=true) at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/sql/sql_parse.cc:2831
#21 0x0000000002470e23 in mysql_parse (thd=0x7f6134913df0, parser_state=0x7f6501cb3eb0) at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/sql/sql_parse.cc:5621
#22 0x00000000024660bb in dispatch_command (thd=0x7f6134913df0, com_data=0x7f6501cb4650, command=COM_QUERY) at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/sql/sql_parse.cc:1495
#23 0x0000000002464fe7 in do_command (thd=0x7f6134913df0) at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/sql/sql_parse.cc:1034
#24 0x0000000002597c03 in handle_connection (arg=0x7ea03b0) at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/sql/conn_handler/connection_handler_per_thread.cc:313
#25 0x0000000002c7b834 in pfs_spawn_thread (arg=0x939e3f0) at /data/jenkins/workspace/stonedb5.7-zsl-centos7.9/storage/perfschema/pfs.cc:2197
#26 0x00007f65514c6ea5 in start_thread (arg=0x7f6501cb5700) at pthread_create.c:307
#27 0x00007f654f8fdb0d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
内存拷贝剖析:
内存拷贝的外围函数:
TempTableForSubquery::ResetToTemplate
void TempTableForSubquery::ResetToTemplate(bool rough) {if (!template_filter) return;
for (uint i = no_global_virt_cols; i < virt_cols.size(); i++) delete virt_cols[i];
virt_cols.resize(template_virt_cols.size());
for (uint i = 0; i < template_virt_cols.size(); i++) virt_cols[i] = template_virt_cols[i];
for (uint i = 0; i < attrs.size(); i++) {void *orig_buf = (*attrs[i]).buffer;
*attrs[i] = *template_attrs[i];
(*attrs[i]).buffer = orig_buf;
}
filter = *template_filter;
for (int i = 0; i < no_global_virt_cols; i++)
if (!virt_cols_for_having[i]) virt_cols[i]->SetMultiIndex(filter.mind);
having_conds = template_having_conds;
order_by = template_order_by;
mode = template_mode;
no_obj = 0;
if (rough)
rough_materialized = false;
else
materialized = false;
no_materialized = 0;
rough_is_empty = common::Tribool();}
filter = *template_filter;
for (int i = 0; i < no_global_virt_cols; i++)
if (!virt_cols_for_having[i]) virt_cols[i]->SetMultiIndex(filter.mind);
函数剖析剖析:
- TempTableForSubquery::ResetToTemplate 函数将 *template_filter 深拷贝给 filter
- 然而在该函数中只用到了 filter.mind
- 尝试防止深拷贝赋值,间接应用 template_filter->mind
TempTableForSubquery::ResetToTemplate 函数优化
优化目标:
- 防止给 filter 的深拷贝赋值, 间接应用 template_filter 的数据
优化危险:
- 在函数执行中,如果其余中央应用到了 filter, 则用的是未被赋值的数据
- 然而在慢的子查问中, 没有并行处理, 只有单线程程序遍历子表
优化后的代码:
void TempTableForSubquery::ResetToTemplate(bool rough) {if (!template_filter) return;
for (uint i = no_global_virt_cols; i < virt_cols.size(); i++) delete virt_cols[i];
virt_cols.resize(template_virt_cols.size());
for (uint i = 0; i < template_virt_cols.size(); i++) virt_cols[i] = template_virt_cols[i];
for (uint i = 0; i < attrs.size(); i++) {void *orig_buf = (*attrs[i]).buffer;
*attrs[i] = *template_attrs[i];
(*attrs[i]).buffer = orig_buf;
}
/*
filter = *template_filter;
for (int i = 0; i < no_global_virt_cols; i++)
if (!virt_cols_for_having[i]) virt_cols[i]->SetMultiIndex(filter.mind);
*/
//filter = *template_filter;
for (int i = 0; i < no_global_virt_cols; i++)
if (!virt_cols_for_having[i]) virt_cols[i]->SetMultiIndex(template_filter->mind);
having_conds = template_having_conds;
order_by = template_order_by;
mode = template_mode;
no_obj = 0;
if (rough)
rough_materialized = false;
else
materialized = false;
no_materialized = 0;
rough_is_empty = common::Tribool();}
//filter = *template_filter;
for (int i = 0; i < no_global_virt_cols; i++)
if (!virt_cols_for_having[i]) virt_cols[i]->SetMultiIndex(template_filter->mind);
优化后的子查问耗时统计:
[root@localhost install]# time /stonedb57/install/bin/mysql -D tpch -e " select
> o_orderpriority,
> count(*) as order_count
> from
> orders
> where
> o_orderdate >= date '1993-07-01'
> and o_orderdate < date '1993-07-01' + interval '3' month
> and exists (
> select
> *
> from
> lineitem
> where
> l_orderkey = o_orderkey
> and l_commitdate < l_receiptdate
> )
> group by
> o_orderpriority
> order by
> o_orderpriority ;"
+-----------------+-------------+
| o_orderpriority | order_count |
+-----------------+-------------+
| 1-URGENT | 114839 |
| 2-HIGH | 114276 |
| 3-MEDIUM | 114716 |
| 4-NOT SPECIFIED | 114913 |
| 5-LOW | 114927 |
+-----------------+-------------+
real 2m3.882s
user 0m0.003s
sys 0m0.011s
优化后的火焰图:
优化后的函数执行统计:
[2022-07-15 13:52:26.284833] [4389] [INFO] [parameterized_filter.cpp:1046] MSG: UpdateMultiIndex: descriptorsNum : 2
[2022-07-15 13:52:26.855408] [4389] [INFO] [parameterized_filter.cpp:1329] MSG: Timer 0.570265 : ApplyDescriptor: Parallel : task_num : 25
[2022-07-15 13:52:40.566920] [4389] [INFO] [parameterized_filter.cpp:1329] MSG: Timer 1.139076 : ApplyDescriptor: Parallel : task_num : 24
[2022-07-15 13:52:40.601432] [4389] [INFO] [parameterized_filter.cpp:1046] MSG: UpdateMultiIndex: descriptorsNum : 2
[2022-07-15 13:52:40.734770] [4389] [INFO] [parameterized_filter.cpp:1329] MSG: Timer 0.133161 : ApplyDescriptor: Parallel : task_num : 25
[2022-07-15 13:52:53.498355] [4389] [INFO] [parameterized_filter.cpp:1329] MSG: Timer 2.275437 : ApplyDescriptor: Parallel : task_num : 24
[2022-07-15 13:52:53.499486] [4389] [INFO] [parameterized_filter.cpp:1046] MSG: UpdateMultiIndex: descriptorsNum : 3
[2022-07-15 13:52:53.599769] [4389] [INFO] [parameterized_filter.cpp:1329] MSG: Timer 0.100144 : ApplyDescriptor: Parallel : task_num : 25
[2022-07-15 13:52:54.772548] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.162256 : EvaluatePackImpl: midCheckNum : 2419 opExistNum: 2419 opOther : 0
[2022-07-15 13:52:56.028205] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.242960 : EvaluatePackImpl: midCheckNum : 2395 opExistNum: 2395 opOther : 0
[2022-07-15 13:52:56.845059] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.803507 : EvaluatePackImpl: midCheckNum : 2432 opExistNum: 2432 opOther : 0
[2022-07-15 13:52:57.715523] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.863239 : EvaluatePackImpl: midCheckNum : 2499 opExistNum: 2499 opOther : 0
[2022-07-15 13:52:58.992723] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.242236 : EvaluatePackImpl: midCheckNum : 2503 opExistNum: 2503 opOther : 0
[2022-07-15 13:53:00.217928] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.213203 : EvaluatePackImpl: midCheckNum : 2531 opExistNum: 2531 opOther : 0
[2022-07-15 13:53:01.405210] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.175979 : EvaluatePackImpl: midCheckNum : 2536 opExistNum: 2536 opOther : 0
[2022-07-15 13:53:02.721667] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.304795 : EvaluatePackImpl: midCheckNum : 2529 opExistNum: 2529 opOther : 0
[2022-07-15 13:53:03.943302] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.207621 : EvaluatePackImpl: midCheckNum : 2496 opExistNum: 2496 opOther : 0
[2022-07-15 13:53:04.705578] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.753813 : EvaluatePackImpl: midCheckNum : 2501 opExistNum: 2501 opOther : 0
[2022-07-15 13:53:05.425500] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.712933 : EvaluatePackImpl: midCheckNum : 2582 opExistNum: 2582 opOther : 0
[2022-07-15 13:53:06.038757] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.607064 : EvaluatePackImpl: midCheckNum : 2510 opExistNum: 2510 opOther : 0
[2022-07-15 13:53:07.155701] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.111036 : EvaluatePackImpl: midCheckNum : 2530 opExistNum: 2530 opOther : 0
[2022-07-15 13:53:08.007385] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.838875 : EvaluatePackImpl: midCheckNum : 2553 opExistNum: 2553 opOther : 0
[2022-07-15 13:53:08.720867] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.706520 : EvaluatePackImpl: midCheckNum : 2547 opExistNum: 2547 opOther : 0
[2022-07-15 13:53:09.819720] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.092728 : EvaluatePackImpl: midCheckNum : 2481 opExistNum: 2481 opOther : 0
[2022-07-15 13:53:10.807612] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.979449 : EvaluatePackImpl: midCheckNum : 2488 opExistNum: 2488 opOther : 0
[2022-07-15 13:53:12.092490] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.272598 : EvaluatePackImpl: midCheckNum : 2485 opExistNum: 2485 opOther : 0
[2022-07-15 13:53:13.361658] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.256283 : EvaluatePackImpl: midCheckNum : 2514 opExistNum: 2514 opOther : 0
[2022-07-15 13:53:14.332579] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.958135 : EvaluatePackImpl: midCheckNum : 2526 opExistNum: 2526 opOther : 0
[2022-07-15 13:53:15.044380] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.704629 : EvaluatePackImpl: midCheckNum : 2414 opExistNum: 2414 opOther : 0
[2022-07-15 13:53:15.788765] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.737335 : EvaluatePackImpl: midCheckNum : 2453 opExistNum: 2453 opOther : 0
[2022-07-15 13:53:16.815655] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.014300 : EvaluatePackImpl: midCheckNum : 2584 opExistNum: 2584 opOther : 0
[2022-07-15 13:53:17.569081] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.746169 : EvaluatePackImpl: midCheckNum : 2567 opExistNum: 2567 opOther : 0
[2022-07-15 13:53:18.242416] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.666127 : EvaluatePackImpl: midCheckNum : 2592 opExistNum: 2592 opOther : 0
[2022-07-15 13:53:18.841194] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.592804 : EvaluatePackImpl: midCheckNum : 2532 opExistNum: 2532 opOther : 0
[2022-07-15 13:53:19.449638] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.602607 : EvaluatePackImpl: midCheckNum : 2536 opExistNum: 2536 opOther : 0
[2022-07-15 13:53:20.078834] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.623290 : EvaluatePackImpl: midCheckNum : 2560 opExistNum: 2560 opOther : 0
[2022-07-15 13:53:20.682758] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.597753 : EvaluatePackImpl: midCheckNum : 2488 opExistNum: 2488 opOther : 0
[2022-07-15 13:53:21.909071] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.220391 : EvaluatePackImpl: midCheckNum : 2522 opExistNum: 2522 opOther : 0
[2022-07-15 13:53:22.680820] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.762596 : EvaluatePackImpl: midCheckNum : 2450 opExistNum: 2450 opOther : 0
[2022-07-15 13:53:23.456759] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.768765 : EvaluatePackImpl: midCheckNum : 2485 opExistNum: 2485 opOther : 0
[2022-07-15 13:53:24.632891] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.163480 : EvaluatePackImpl: midCheckNum : 2553 opExistNum: 2553 opOther : 0
[2022-07-15 13:53:25.399882] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.758609 : EvaluatePackImpl: midCheckNum : 2523 opExistNum: 2523 opOther : 0
[2022-07-15 13:53:26.113650] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.706678 : EvaluatePackImpl: midCheckNum : 2566 opExistNum: 2566 opOther : 0
[2022-07-15 13:53:26.724415] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.604565 : EvaluatePackImpl: midCheckNum : 2532 opExistNum: 2532 opOther : 0
[2022-07-15 13:53:27.345257] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.614842 : EvaluatePackImpl: midCheckNum : 2548 opExistNum: 2548 opOther : 0
[2022-07-15 13:53:27.971060] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.619776 : EvaluatePackImpl: midCheckNum : 2568 opExistNum: 2568 opOther : 0
[2022-07-15 13:53:28.585986] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.608778 : EvaluatePackImpl: midCheckNum : 2603 opExistNum: 2603 opOther : 0
[2022-07-15 13:53:29.548147] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.956269 : EvaluatePackImpl: midCheckNum : 2557 opExistNum: 2557 opOther : 0
[2022-07-15 13:53:30.711536] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.150871 : EvaluatePackImpl: midCheckNum : 2582 opExistNum: 2582 opOther : 0
[2022-07-15 13:53:31.428487] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.709066 : EvaluatePackImpl: midCheckNum : 2494 opExistNum: 2494 opOther : 0
[2022-07-15 13:53:32.086644] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.651425 : EvaluatePackImpl: midCheckNum : 2556 opExistNum: 2556 opOther : 0
[2022-07-15 13:53:32.670591] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.577609 : EvaluatePackImpl: midCheckNum : 2509 opExistNum: 2509 opOther : 0
[2022-07-15 13:53:33.282904] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.606545 : EvaluatePackImpl: midCheckNum : 2531 opExistNum: 2531 opOther : 0
[2022-07-15 13:53:34.542438] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.253332 : EvaluatePackImpl: midCheckNum : 2569 opExistNum: 2569 opOther : 0
[2022-07-15 13:53:35.618634] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.063963 : EvaluatePackImpl: midCheckNum : 2458 opExistNum: 2458 opOther : 0
[2022-07-15 13:53:36.319143] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.692643 : EvaluatePackImpl: midCheckNum : 2455 opExistNum: 2455 opOther : 0
[2022-07-15 13:53:37.556045] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.230604 : EvaluatePackImpl: midCheckNum : 2508 opExistNum: 2508 opOther : 0
[2022-07-15 13:53:38.404526] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.836627 : EvaluatePackImpl: midCheckNum : 2497 opExistNum: 2497 opOther : 0
[2022-07-15 13:53:39.424084] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.012406 : EvaluatePackImpl: midCheckNum : 2522 opExistNum: 2522 opOther : 0
[2022-07-15 13:53:40.499771] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.063877 : EvaluatePackImpl: midCheckNum : 2440 opExistNum: 2440 opOther : 0
[2022-07-15 13:53:41.917253] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.404300 : EvaluatePackImpl: midCheckNum : 2572 opExistNum: 2572 opOther : 0
[2022-07-15 13:53:43.288414] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.358635 : EvaluatePackImpl: midCheckNum : 2548 opExistNum: 2548 opOther : 0
[2022-07-15 13:53:44.343393] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.046631 : EvaluatePackImpl: midCheckNum : 2528 opExistNum: 2528 opOther : 0
[2022-07-15 13:53:45.408471] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.052752 : EvaluatePackImpl: midCheckNum : 2473 opExistNum: 2473 opOther : 0
[2022-07-15 13:53:46.138239] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.723007 : EvaluatePackImpl: midCheckNum : 2462 opExistNum: 2462 opOther : 0
[2022-07-15 13:53:46.765123] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.620031 : EvaluatePackImpl: midCheckNum : 2470 opExistNum: 2470 opOther : 0
[2022-07-15 13:53:47.351674] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.580676 : EvaluatePackImpl: midCheckNum : 2454 opExistNum: 2454 opOther : 0
[2022-07-15 13:53:47.950779] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.585015 : EvaluatePackImpl: midCheckNum : 2431 opExistNum: 2431 opOther : 0
[2022-07-15 13:53:48.554604] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.597745 : EvaluatePackImpl: midCheckNum : 2515 opExistNum: 2515 opOther : 0
[2022-07-15 13:53:49.166164] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.605608 : EvaluatePackImpl: midCheckNum : 2542 opExistNum: 2542 opOther : 0
[2022-07-15 13:53:49.805202] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.633093 : EvaluatePackImpl: midCheckNum : 2633 opExistNum: 2633 opOther : 0
[2022-07-15 13:53:50.419891] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.608976 : EvaluatePackImpl: midCheckNum : 2482 opExistNum: 2482 opOther : 0
[2022-07-15 13:53:51.463714] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.037705 : EvaluatePackImpl: midCheckNum : 2528 opExistNum: 2528 opOther : 0
[2022-07-15 13:53:52.220343] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.748792 : EvaluatePackImpl: midCheckNum : 2490 opExistNum: 2490 opOther : 0
[2022-07-15 13:53:52.944621] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.717023 : EvaluatePackImpl: midCheckNum : 2589 opExistNum: 2589 opOther : 0
[2022-07-15 13:53:53.548593] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.597596 : EvaluatePackImpl: midCheckNum : 2520 opExistNum: 2520 opOther : 0
[2022-07-15 13:53:54.142085] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.587673 : EvaluatePackImpl: midCheckNum : 2508 opExistNum: 2508 opOther : 0
[2022-07-15 13:53:54.764207] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.615820 : EvaluatePackImpl: midCheckNum : 2592 opExistNum: 2592 opOther : 0
[2022-07-15 13:53:55.356624] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.586597 : EvaluatePackImpl: midCheckNum : 2498 opExistNum: 2498 opOther : 0
[2022-07-15 13:53:55.977148] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.614421 : EvaluatePackImpl: midCheckNum : 2544 opExistNum: 2544 opOther : 0
[2022-07-15 13:53:56.563241] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.580036 : EvaluatePackImpl: midCheckNum : 2464 opExistNum: 2464 opOther : 0
[2022-07-15 13:53:57.166399] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.597472 : EvaluatePackImpl: midCheckNum : 2533 opExistNum: 2533 opOther : 0
[2022-07-15 13:53:58.204905] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.032385 : EvaluatePackImpl: midCheckNum : 2521 opExistNum: 2521 opOther : 0
[2022-07-15 13:53:59.036773] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.823222 : EvaluatePackImpl: midCheckNum : 2485 opExistNum: 2485 opOther : 0
[2022-07-15 13:53:59.778520] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.734540 : EvaluatePackImpl: midCheckNum : 2520 opExistNum: 2520 opOther : 0
[2022-07-15 13:54:00.407824] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.623028 : EvaluatePackImpl: midCheckNum : 2507 opExistNum: 2507 opOther : 0
[2022-07-15 13:54:01.009275] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.595776 : EvaluatePackImpl: midCheckNum : 2471 opExistNum: 2471 opOther : 0
[2022-07-15 13:54:01.640618] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.625183 : EvaluatePackImpl: midCheckNum : 2541 opExistNum: 2541 opOther : 0
[2022-07-15 13:54:02.766695] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.113166 : EvaluatePackImpl: midCheckNum : 2536 opExistNum: 2536 opOther : 0
[2022-07-15 13:54:03.759812] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.981176 : EvaluatePackImpl: midCheckNum : 2494 opExistNum: 2494 opOther : 0
[2022-07-15 13:54:04.471812] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.704585 : EvaluatePackImpl: midCheckNum : 2493 opExistNum: 2493 opOther : 0
[2022-07-15 13:54:05.144059] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.665925 : EvaluatePackImpl: midCheckNum : 2498 opExistNum: 2498 opOther : 0
[2022-07-15 13:54:05.767033] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.615734 : EvaluatePackImpl: midCheckNum : 2516 opExistNum: 2516 opOther : 0
[2022-07-15 13:54:06.363461] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.590692 : EvaluatePackImpl: midCheckNum : 2589 opExistNum: 2589 opOther : 0
[2022-07-15 13:54:06.955363] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.586104 : EvaluatePackImpl: midCheckNum : 2539 opExistNum: 2539 opOther : 0
[2022-07-15 13:54:07.555813] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.594550 : EvaluatePackImpl: midCheckNum : 2497 opExistNum: 2497 opOther : 0
[2022-07-15 13:54:08.143879] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.581922 : EvaluatePackImpl: midCheckNum : 2501 opExistNum: 2501 opOther : 0
[2022-07-15 13:54:09.249754] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.099442 : EvaluatePackImpl: midCheckNum : 2477 opExistNum: 2477 opOther : 0
[2022-07-15 13:54:10.237164] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.975106 : EvaluatePackImpl: midCheckNum : 2446 opExistNum: 2446 opOther : 0
[2022-07-15 13:54:10.930208] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.686225 : EvaluatePackImpl: midCheckNum : 2448 opExistNum: 2448 opOther : 0
[2022-07-15 13:54:11.574280] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.637130 : EvaluatePackImpl: midCheckNum : 2483 opExistNum: 2483 opOther : 0
[2022-07-15 13:54:12.629646] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.049036 : EvaluatePackImpl: midCheckNum : 2486 opExistNum: 2486 opOther : 0
[2022-07-15 13:54:13.373287] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.735317 : EvaluatePackImpl: midCheckNum : 2478 opExistNum: 2478 opOther : 0
[2022-07-15 13:54:14.364716] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.984350 : EvaluatePackImpl: midCheckNum : 2572 opExistNum: 2572 opOther : 0
[2022-07-15 13:54:15.130172] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.757302 : EvaluatePackImpl: midCheckNum : 2509 opExistNum: 2509 opOther : 0
[2022-07-15 13:54:16.148157] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.011026 : EvaluatePackImpl: midCheckNum : 2565 opExistNum: 2565 opOther : 0
[2022-07-15 13:54:17.306554] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.146335 : EvaluatePackImpl: midCheckNum : 2455 opExistNum: 2455 opOther : 0
[2022-07-15 13:54:18.284635] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.965196 : EvaluatePackImpl: midCheckNum : 2446 opExistNum: 2446 opOther : 0
[2022-07-15 13:54:18.463169] [4367] [INFO] [engine.cpp:1352] MSG: Command: select 6/6, update 0/0, insert 0/0, load 0/0, queries 0/11
[2022-07-15 13:54:18.463309] [4367] [INFO] [engine.cpp:1364] MSG: Select: 0/3, Loaded: 0/0(0/0), dup: 0/0, insert: 0/0, failed insert: 0/0, update: 0/0
[2022-07-15 13:54:18.938470] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.646453 : EvaluatePackImpl: midCheckNum : 2451 opExistNum: 2451 opOther : 0
[2022-07-15 13:54:19.540054] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.595375 : EvaluatePackImpl: midCheckNum : 2548 opExistNum: 2548 opOther : 0
[2022-07-15 13:54:20.455440] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.909232 : EvaluatePackImpl: midCheckNum : 2441 opExistNum: 2441 opOther : 0
[2022-07-15 13:54:21.306403] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.840245 : EvaluatePackImpl: midCheckNum : 2480 opExistNum: 2480 opOther : 0
[2022-07-15 13:54:22.039390] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.725760 : EvaluatePackImpl: midCheckNum : 2525 opExistNum: 2525 opOther : 0
[2022-07-15 13:54:22.675895] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.629600 : EvaluatePackImpl: midCheckNum : 2424 opExistNum: 2424 opOther : 0
[2022-07-15 13:54:23.273787] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.591655 : EvaluatePackImpl: midCheckNum : 2547 opExistNum: 2547 opOther : 0
[2022-07-15 13:54:23.852188] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.572307 : EvaluatePackImpl: midCheckNum : 2369 opExistNum: 2369 opOther : 0
[2022-07-15 13:54:24.453597] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.595455 : EvaluatePackImpl: midCheckNum : 2500 opExistNum: 2500 opOther : 0
[2022-07-15 13:54:25.047846] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.587919 : EvaluatePackImpl: midCheckNum : 2472 opExistNum: 2472 opOther : 0
[2022-07-15 13:54:25.644905] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.591146 : EvaluatePackImpl: midCheckNum : 2528 opExistNum: 2528 opOther : 0
[2022-07-15 13:54:26.257348] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.606613 : EvaluatePackImpl: midCheckNum : 2570 opExistNum: 2570 opOther : 0
[2022-07-15 13:54:26.870401] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.607013 : EvaluatePackImpl: midCheckNum : 2511 opExistNum: 2511 opOther : 0
[2022-07-15 13:54:28.184342] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.301200 : EvaluatePackImpl: midCheckNum : 2559 opExistNum: 2559 opOther : 0
[2022-07-15 13:54:29.209191] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.012236 : EvaluatePackImpl: midCheckNum : 2481 opExistNum: 2481 opOther : 0
[2022-07-15 13:54:29.940006] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.723404 : EvaluatePackImpl: midCheckNum : 2524 opExistNum: 2524 opOther : 0
[2022-07-15 13:54:30.931584] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.984378 : EvaluatePackImpl: midCheckNum : 2571 opExistNum: 2571 opOther : 0
[2022-07-15 13:54:32.388880] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.444634 : EvaluatePackImpl: midCheckNum : 2595 opExistNum: 2595 opOther : 0
[2022-07-15 13:54:33.606083] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.204494 : EvaluatePackImpl: midCheckNum : 2598 opExistNum: 2598 opOther : 0
[2022-07-15 13:54:34.658785] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.040517 : EvaluatePackImpl: midCheckNum : 2463 opExistNum: 2463 opOther : 0
[2022-07-15 13:54:35.701818] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.035026 : EvaluatePackImpl: midCheckNum : 2505 opExistNum: 2505 opOther : 0
[2022-07-15 13:54:36.505706] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.794936 : EvaluatePackImpl: midCheckNum : 2508 opExistNum: 2508 opOther : 0
[2022-07-15 13:54:37.323477] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.810813 : EvaluatePackImpl: midCheckNum : 2511 opExistNum: 2511 opOther : 0
[2022-07-15 13:54:38.481950] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.150879 : EvaluatePackImpl: midCheckNum : 2451 opExistNum: 2451 opOther : 0
[2022-07-15 13:54:39.726706] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.231374 : EvaluatePackImpl: midCheckNum : 2434 opExistNum: 2434 opOther : 0
[2022-07-15 13:54:40.969822] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.234557 : EvaluatePackImpl: midCheckNum : 2627 opExistNum: 2627 opOther : 0
[2022-07-15 13:54:42.155110] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.175840 : EvaluatePackImpl: midCheckNum : 2395 opExistNum: 2395 opOther : 0
[2022-07-15 13:54:43.229426] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.061732 : EvaluatePackImpl: midCheckNum : 2469 opExistNum: 2469 opOther : 0
[2022-07-15 13:54:44.607685] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.365658 : EvaluatePackImpl: midCheckNum : 2534 opExistNum: 2534 opOther : 0
[2022-07-15 13:54:45.641305] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.020874 : EvaluatePackImpl: midCheckNum : 2474 opExistNum: 2474 opOther : 0
[2022-07-15 13:54:47.136255] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.482406 : EvaluatePackImpl: midCheckNum : 2604 opExistNum: 2604 opOther : 0
[2022-07-15 13:54:48.124300] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.975420 : EvaluatePackImpl: midCheckNum : 2509 opExistNum: 2509 opOther : 0
[2022-07-15 13:54:48.812883] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.680532 : EvaluatePackImpl: midCheckNum : 2409 opExistNum: 2409 opOther : 0
[2022-07-15 13:54:49.753476] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.933551 : EvaluatePackImpl: midCheckNum : 2527 opExistNum: 2527 opOther : 0
[2022-07-15 13:54:50.564495] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.801315 : EvaluatePackImpl: midCheckNum : 2454 opExistNum: 2454 opOther : 0
[2022-07-15 13:54:51.179254] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.607389 : EvaluatePackImpl: midCheckNum : 2490 opExistNum: 2490 opOther : 0
[2022-07-15 13:54:51.765133] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.579482 : EvaluatePackImpl: midCheckNum : 2578 opExistNum: 2578 opOther : 0
[2022-07-15 13:54:52.788185] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.017181 : EvaluatePackImpl: midCheckNum : 2494 opExistNum: 2494 opOther : 0
[2022-07-15 13:54:53.813675] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.012892 : EvaluatePackImpl: midCheckNum : 2669 opExistNum: 2669 opOther : 0
[2022-07-15 13:54:54.511224] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.690541 : EvaluatePackImpl: midCheckNum : 2492 opExistNum: 2492 opOther : 0
[2022-07-15 13:54:55.624461] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.106066 : EvaluatePackImpl: midCheckNum : 2578 opExistNum: 2578 opOther : 0
[2022-07-15 13:54:56.930359] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.293473 : EvaluatePackImpl: midCheckNum : 2476 opExistNum: 2476 opOther : 0
[2022-07-15 13:54:58.249645] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.306475 : EvaluatePackImpl: midCheckNum : 2365 opExistNum: 2365 opOther : 0
[2022-07-15 13:54:59.651202] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.388647 : EvaluatePackImpl: midCheckNum : 2514 opExistNum: 2514 opOther : 0
[2022-07-15 13:55:00.718714] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.055301 : EvaluatePackImpl: midCheckNum : 2472 opExistNum: 2472 opOther : 0
[2022-07-15 13:55:01.428360] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.700675 : EvaluatePackImpl: midCheckNum : 2485 opExistNum: 2485 opOther : 0
[2022-07-15 13:55:02.084101] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.648394 : EvaluatePackImpl: midCheckNum : 2500 opExistNum: 2500 opOther : 0
[2022-07-15 13:55:02.700673] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.610308 : EvaluatePackImpl: midCheckNum : 2607 opExistNum: 2607 opOther : 0
[2022-07-15 13:55:03.290142] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.583285 : EvaluatePackImpl: midCheckNum : 2518 opExistNum: 2518 opOther : 0
[2022-07-15 13:55:03.966766] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.670653 : EvaluatePackImpl: midCheckNum : 2539 opExistNum: 2539 opOther : 0
[2022-07-15 13:55:04.595208] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.621345 : EvaluatePackImpl: midCheckNum : 2457 opExistNum: 2457 opOther : 0
[2022-07-15 13:55:05.172089] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.570698 : EvaluatePackImpl: midCheckNum : 2459 opExistNum: 2459 opOther : 0
[2022-07-15 13:55:05.747866] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.569881 : EvaluatePackImpl: midCheckNum : 2433 opExistNum: 2433 opOther : 0
[2022-07-15 13:55:06.472296] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.718088 : EvaluatePackImpl: midCheckNum : 2503 opExistNum: 2503 opOther : 0
[2022-07-15 13:55:07.157264] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.677598 : EvaluatePackImpl: midCheckNum : 2448 opExistNum: 2448 opOther : 0
[2022-07-15 13:55:07.777932] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.613473 : EvaluatePackImpl: midCheckNum : 2548 opExistNum: 2548 opOther : 0
[2022-07-15 13:55:08.359206] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.575610 : EvaluatePackImpl: midCheckNum : 2526 opExistNum: 2526 opOther : 0
[2022-07-15 13:55:08.948364] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.583310 : EvaluatePackImpl: midCheckNum : 2479 opExistNum: 2479 opOther : 0
[2022-07-15 13:55:09.553353] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.598801 : EvaluatePackImpl: midCheckNum : 2511 opExistNum: 2511 opOther : 0
[2022-07-15 13:55:10.159520] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.599815 : EvaluatePackImpl: midCheckNum : 2567 opExistNum: 2567 opOther : 0
[2022-07-15 13:55:10.751699] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.585804 : EvaluatePackImpl: midCheckNum : 2491 opExistNum: 2491 opOther : 0
[2022-07-15 13:55:11.340739] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.582766 : EvaluatePackImpl: midCheckNum : 2467 opExistNum: 2467 opOther : 0
[2022-07-15 13:55:11.957585] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.610508 : EvaluatePackImpl: midCheckNum : 2551 opExistNum: 2551 opOther : 0
[2022-07-15 13:55:12.551779] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.588050 : EvaluatePackImpl: midCheckNum : 2496 opExistNum: 2496 opOther : 0
[2022-07-15 13:55:13.136528] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.578720 : EvaluatePackImpl: midCheckNum : 2460 opExistNum: 2460 opOther : 0
[2022-07-15 13:55:13.728816] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.586453 : EvaluatePackImpl: midCheckNum : 2504 opExistNum: 2504 opOther : 0
[2022-07-15 13:55:14.727803] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.992841 : EvaluatePackImpl: midCheckNum : 2493 opExistNum: 2493 opOther : 0
[2022-07-15 13:55:15.517931] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.781134 : EvaluatePackImpl: midCheckNum : 2522 opExistNum: 2522 opOther : 0
[2022-07-15 13:55:16.185772] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.660559 : EvaluatePackImpl: midCheckNum : 2383 opExistNum: 2383 opOther : 0
[2022-07-15 13:55:17.377231] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.184304 : EvaluatePackImpl: midCheckNum : 2431 opExistNum: 2431 opOther : 0
[2022-07-15 13:55:18.463788] [4367] [INFO] [engine.cpp:1352] MSG: Command: select 0/6, update 0/0, insert 0/0, load 0/0, queries 0/11
[2022-07-15 13:55:18.463914] [4367] [INFO] [engine.cpp:1364] MSG: Select: 0/3, Loaded: 0/0(0/0), dup: 0/0, insert: 0/0, failed insert: 0/0, update: 0/0
[2022-07-15 13:55:18.581889] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.192137 : EvaluatePackImpl: midCheckNum : 2412 opExistNum: 2412 opOther : 0
[2022-07-15 13:55:19.887856] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.293773 : EvaluatePackImpl: midCheckNum : 2523 opExistNum: 2523 opOther : 0
[2022-07-15 13:55:21.073454] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.172642 : EvaluatePackImpl: midCheckNum : 2456 opExistNum: 2456 opOther : 0
[2022-07-15 13:55:22.278521] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.192222 : EvaluatePackImpl: midCheckNum : 2540 opExistNum: 2540 opOther : 0
[2022-07-15 13:55:23.282938] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.991654 : EvaluatePackImpl: midCheckNum : 2493 opExistNum: 2493 opOther : 0
[2022-07-15 13:55:23.960842] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.670682 : EvaluatePackImpl: midCheckNum : 2459 opExistNum: 2459 opOther : 0
[2022-07-15 13:55:24.619285] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.652037 : EvaluatePackImpl: midCheckNum : 2532 opExistNum: 2532 opOther : 0
[2022-07-15 13:55:25.220509] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.594069 : EvaluatePackImpl: midCheckNum : 2470 opExistNum: 2470 opOther : 0
[2022-07-15 13:55:25.817754] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.591236 : EvaluatePackImpl: midCheckNum : 2520 opExistNum: 2520 opOther : 0
[2022-07-15 13:55:26.471327] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.646094 : EvaluatePackImpl: midCheckNum : 2510 opExistNum: 2510 opOther : 0
[2022-07-15 13:55:27.047235] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.569672 : EvaluatePackImpl: midCheckNum : 2489 opExistNum: 2489 opOther : 0
[2022-07-15 13:55:27.615894] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.562406 : EvaluatePackImpl: midCheckNum : 2479 opExistNum: 2479 opOther : 0
[2022-07-15 13:55:28.194302] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.572400 : EvaluatePackImpl: midCheckNum : 2459 opExistNum: 2459 opOther : 0
[2022-07-15 13:55:28.799743] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.598065 : EvaluatePackImpl: midCheckNum : 2607 opExistNum: 2607 opOther : 0
[2022-07-15 13:55:29.792406] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.986511 : EvaluatePackImpl: midCheckNum : 2435 opExistNum: 2435 opOther : 0
[2022-07-15 13:55:30.545269] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.744540 : EvaluatePackImpl: midCheckNum : 2451 opExistNum: 2451 opOther : 0
[2022-07-15 13:55:31.231939] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.679263 : EvaluatePackImpl: midCheckNum : 2464 opExistNum: 2464 opOther : 0
[2022-07-15 13:55:31.817683] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.579358 : EvaluatePackImpl: midCheckNum : 2449 opExistNum: 2449 opOther : 0
[2022-07-15 13:55:32.409613] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.585870 : EvaluatePackImpl: midCheckNum : 2560 opExistNum: 2560 opOther : 0
[2022-07-15 13:55:32.983891] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.568173 : EvaluatePackImpl: midCheckNum : 2440 opExistNum: 2440 opOther : 0
[2022-07-15 13:55:33.894300] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.904045 : EvaluatePackImpl: midCheckNum : 2525 opExistNum: 2525 opOther : 0
[2022-07-15 13:55:34.731099] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.827102 : EvaluatePackImpl: midCheckNum : 2588 opExistNum: 2588 opOther : 0
[2022-07-15 13:55:35.435901] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.697930 : EvaluatePackImpl: midCheckNum : 2509 opExistNum: 2509 opOther : 0
[2022-07-15 13:55:36.028046] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.585293 : EvaluatePackImpl: midCheckNum : 2426 opExistNum: 2426 opOther : 0
[2022-07-15 13:55:36.638975] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.604967 : EvaluatePackImpl: midCheckNum : 2549 opExistNum: 2549 opOther : 0
[2022-07-15 13:55:37.222535] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.577523 : EvaluatePackImpl: midCheckNum : 2482 opExistNum: 2482 opOther : 0
[2022-07-15 13:55:37.825454] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.596607 : EvaluatePackImpl: midCheckNum : 2585 opExistNum: 2585 opOther : 0
[2022-07-15 13:55:38.408216] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.576638 : EvaluatePackImpl: midCheckNum : 2503 opExistNum: 2503 opOther : 0
[2022-07-15 13:55:38.999902] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.585620 : EvaluatePackImpl: midCheckNum : 2507 opExistNum: 2507 opOther : 0
[2022-07-15 13:55:39.588231] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.582293 : EvaluatePackImpl: midCheckNum : 2519 opExistNum: 2519 opOther : 0
[2022-07-15 13:55:40.348127] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.753694 : EvaluatePackImpl: midCheckNum : 2475 opExistNum: 2475 opOther : 0
[2022-07-15 13:55:41.601544] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.240901 : EvaluatePackImpl: midCheckNum : 2437 opExistNum: 2437 opOther : 0
[2022-07-15 13:55:42.444817] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.830079 : EvaluatePackImpl: midCheckNum : 2551 opExistNum: 2551 opOther : 0
[2022-07-15 13:55:43.165620] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.713318 : EvaluatePackImpl: midCheckNum : 2524 opExistNum: 2524 opOther : 0
[2022-07-15 13:55:43.773140] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.600266 : EvaluatePackImpl: midCheckNum : 2482 opExistNum: 2482 opOther : 0
[2022-07-15 13:55:44.381515] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.602006 : EvaluatePackImpl: midCheckNum : 2587 opExistNum: 2587 opOther : 0
[2022-07-15 13:55:44.988063] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.600230 : EvaluatePackImpl: midCheckNum : 2545 opExistNum: 2545 opOther : 0
[2022-07-15 13:55:46.152060] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.154480 : EvaluatePackImpl: midCheckNum : 2593 opExistNum: 2593 opOther : 0
[2022-07-15 13:55:46.884504] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.724163 : EvaluatePackImpl: midCheckNum : 2490 opExistNum: 2490 opOther : 0
[2022-07-15 13:55:47.569163] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.677043 : EvaluatePackImpl: midCheckNum : 2548 opExistNum: 2548 opOther : 0
[2022-07-15 13:55:48.584688] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.008809 : EvaluatePackImpl: midCheckNum : 2492 opExistNum: 2492 opOther : 0
[2022-07-15 13:55:49.724536] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.127222 : EvaluatePackImpl: midCheckNum : 2494 opExistNum: 2494 opOther : 0
[2022-07-15 13:55:50.939800] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.202436 : EvaluatePackImpl: midCheckNum : 2550 opExistNum: 2550 opOther : 0
[2022-07-15 13:55:51.689907] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.741461 : EvaluatePackImpl: midCheckNum : 2447 opExistNum: 2447 opOther : 0
[2022-07-15 13:55:52.368685] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.670465 : EvaluatePackImpl: midCheckNum : 2418 opExistNum: 2418 opOther : 0
[2022-07-15 13:55:53.005904] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.630404 : EvaluatePackImpl: midCheckNum : 2485 opExistNum: 2485 opOther : 0
[2022-07-15 13:55:53.586146] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.573822 : EvaluatePackImpl: midCheckNum : 2511 opExistNum: 2511 opOther : 0
[2022-07-15 13:55:54.170306] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.578209 : EvaluatePackImpl: midCheckNum : 2526 opExistNum: 2526 opOther : 0
[2022-07-15 13:55:54.762202] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.585560 : EvaluatePackImpl: midCheckNum : 2504 opExistNum: 2504 opOther : 0
[2022-07-15 13:55:55.343105] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.574928 : EvaluatePackImpl: midCheckNum : 2540 opExistNum: 2540 opOther : 0
[2022-07-15 13:55:55.888314] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.539491 : EvaluatePackImpl: midCheckNum : 2387 opExistNum: 2387 opOther : 0
[2022-07-15 13:55:56.460935] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.566148 : EvaluatePackImpl: midCheckNum : 2441 opExistNum: 2441 opOther : 0
[2022-07-15 13:55:57.046220] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.579486 : EvaluatePackImpl: midCheckNum : 2455 opExistNum: 2455 opOther : 0
[2022-07-15 13:55:57.646681] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.594315 : EvaluatePackImpl: midCheckNum : 2516 opExistNum: 2516 opOther : 0
[2022-07-15 13:55:58.244458] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.591706 : EvaluatePackImpl: midCheckNum : 2536 opExistNum: 2536 opOther : 0
[2022-07-15 13:55:59.367847] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.117169 : EvaluatePackImpl: midCheckNum : 2508 opExistNum: 2508 opOther : 0
[2022-07-15 13:56:00.174403] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.797889 : EvaluatePackImpl: midCheckNum : 2565 opExistNum: 2565 opOther : 0
[2022-07-15 13:56:00.902783] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 0.721434 : EvaluatePackImpl: midCheckNum : 2564 opExistNum: 2564 opOther : 0
[2022-07-15 13:56:01.969199] [4389] [INFO] [descriptor.cpp:874] MSG: Timer 1.065312 : EvaluatePackImpl: midCheckNum : 2225 opExistNum: 2225 opOther : 0
[2022-07-15 13:56:01.969386] [4389] [INFO] [parameterized_filter.cpp:1376] MSG: Timer 188.369370 : ApplyDescriptor: descEvaluatePackNum : 229
[2022-07-15 13:56:01.969486] [4389] [INFO] [parameterized_filter.cpp:1084] MSG: Timer 188.470001 : UpdateMultiIndex: ApplyDescriptorNum : 2
正文完