2.21 单条SQL性能trace
这个功能与MySQL的profile功能类似，用于统计一条查询在dble内部的各个阶段的耗时情况，用来发现性能瓶颈，改进SQL或者dble配置，达到提高性能的目的。 此功能为session 级别。
1. 可以通过此命令检查trace功能是否开启
mysql> select @@trace;
+---------+
| @@trace |
+---------+
| 0 |
+---------+
1 row in set (0.02 sec)
2. 开启 trace 功能
mysql> set trace =1;
Query OK, 0 rows affected (0.09 sec)
mysql> select @@trace;
+---------+
| @@trace |
+---------+
| 1 |
+---------+
1 row in set (0.00 sec)
3. 单节点查询的trace结果举例
mysql> select * from sharding_two_node where id =1;
+----+--------+-----------+
| id | c_flag | c_decimal |
+----+--------+-----------+
| 1 | 1 | 1.0000 |
+----+--------+-----------+
1 row in set (0.02 sec)
mysql> show trace;
+-------------------+-----------+-----------+--------------+---------------+---------------------------------------------+
| OPERATION | START(ms) | END(ms) | DURATION(ms) | SHARDING_NODE | SQL/REF |
+-------------------+-----------+-----------+--------------+---------------+---------------------------------------------+
| Read SQL | 0.0 | 0.1085 | 0.1085 | - | - |
| Parse SQL | 0.1085 | 0.49607 | 0.38757 | - | - |
| Route Calculation | 0.49607 | 1.274142 | 0.778072 | - | - |
| Prepare to Push | 1.274142 | 1.560543 | 0.286401 | - | - |
| Execute SQL | 1.560543 | 18.711851 | 17.151308 | dn1 | select * from sharding_two_node where id =1 |
| Fetch result | 18.711851 | 18.978213 | 0.266362 | dn1 | select * from sharding_two_node where id =1 |
| Write to Client | 18.711851 | 19.276344 | 0.564493 | - | - |
| Over All | 0.0 | 19.276344 | 19.276344 | - | - |
+-------------------+-----------+-----------+--------------+---------------+---------------------------------------------+
8 rows in set (0.00 sec)
4. 多节点查询的trace结果举例
mysql> select * from sharding_two_node ;
+-----+--------+-----------+
| id | c_flag | c_decimal |
+-----+--------+-----------+
| 513 | 513 | 513.0000 |
| 514 | 514 | 514.0000 |
| 515 | 515 | 515.0000 |
| 516 | 516 | 516.0000 |
| 1 | 1 | 1.0000 |
| 2 | 2 | 2.0000 |
| 3 | 3 | 3.0000 |
| 4 | 4 | 4.0000 |
| 5 | 5 | 5.0000 |
| 7 | 7 | 7.0000 |
| 8 | 8 | 8.0000 |
| 9 | 9 | 9.0000 |
| 10 | 10 | 10.0000 |
| 11 | 11 | 11.0000 |
| 12 | 12 | 12.0000 |
+-----+--------+-----------+
15 rows in set (0.01 sec)
mysql> show trace;
+-------------------+-----------+----------+--------------+---------------+-------------------------------------------+
| OPERATION | START(ms) | END(ms) | DURATION(ms) | SHARDING_NODE | SQL/REF |
+-------------------+-----------+----------+--------------+---------------+-------------------------------------------+
| Read SQL | 0.0 | 0.079175 | 0.079175 | - | - |
| Parse SQL | 0.079175 | 0.637315 | 0.55814 | - | - |
| Route Calculation | 0.637315 | 1.046389 | 0.409074 | - | - |
| Prepare to Push | 1.046389 | 1.465238 | 0.418849 | - | - |
| Execute SQL | 1.465238 | 8.141409 | 6.676171 | dn1 | SELECT * FROM sharding_two_node LIMIT 100 |
| Execute SQL | 1.465238 | 7.59109 | 6.125852 | dn2 | SELECT * FROM sharding_two_node LIMIT 100 |
| Fetch result | 8.141409 | 8.817824 | 0.676415 | dn1 | SELECT * FROM sharding_two_node LIMIT 100 |
| Fetch result | 7.59109 | 8.366718 | 0.775628 | dn2 | SELECT * FROM sharding_two_node LIMIT 100 |
| Write to Client | 7.59109 | 9.324157 | 1.733067 | - | - |
| Over All | 0.0 | 9.324157 | 9.324157 | - | - |
+-------------------+-----------+----------+--------------+---------------+-------------------------------------------+
10 rows in set (0.00 sec)
5. 多节点写入的SQL 的trace结果举例,事实上,这是一个隐式分布式事务
mysql> insert into sharding_two_node values(15,'15',15),(519,'519',519);
Query OK, 2 rows affected (0.06 sec)
mysql> show trace;
+---------------------------------+-----------+-----------+--------------+---------------+--------------------------------------------------------+
| OPERATION | START(ms) | END(ms) | DURATION(ms) | SHARDING_NODE | SQL/REF |
+---------------------------------+-----------+-----------+--------------+---------------+--------------------------------------------------------+
| Read SQL | 0.0 | 0.131959 | 0.131959 | - | - |
| Parse SQL | 0.131959 | 0.601637 | 0.469678 | - | - |
| Route Calculation | 0.601637 | 0.825479 | 0.223842 | - | - |
| Prepare to Push | 0.825479 | 1.025374 | 0.199895 | - | - |
| Execute SQL | 1.025374 | 27.095675 | 26.070301 | dn1 | INSERT INTO sharding_two_node VALUES (15, '15', 15) |
| Execute SQL | 1.025374 | 25.023911 | 23.998537 | dn2 | INSERT INTO sharding_two_node VALUES (519, '519', 519) |
| Fetch result | 27.095675 | 27.405046 | 0.309371 | dn1 | INSERT INTO sharding_two_node VALUES (15, '15', 15) |
| Fetch result | 25.023911 | 26.478398 | 1.454487 | dn2 | INSERT INTO sharding_two_node VALUES (519, '519', 519) |
| Distributed Transaction Prepare | 27.405046 | 27.736411 | 0.331365 | - | - |
| Distributed Transaction Commit | 27.736411 | 57.426311 | 29.6899 | - | - |
| Write to Client | 25.023911 | 57.428266 | 32.404355 | - | - |
| Over All | 0.0 | 57.428266 | 57.428266 | - | - |
+---------------------------------+-----------+-----------+--------------+---------------+--------------------------------------------------------+
12 rows in set (0.00 sec)
6. 复杂查询的trace结果举例
mysql> select count(*) from sharding_two_node;
+----------+
| COUNT(*) |
+----------+
| 20 |
+----------+
1 row in set (0.01 sec)
mysql> show trace;
+-----------------------+-----------+-----------+--------------+-----------------+--------------------------------------------------------------------------+
| OPERATION | START(ms) | END(ms) | DURATION(ms) | SHARDING_NODE | SQL/REF |
+-----------------------+-----------+-----------+--------------+-----------------+--------------------------------------------------------------------------+
| Read SQL | 0.0 | 0.08553 | 0.08553 | - | - |
| Parse SQL | 0.08553 | 0.56987 | 0.48434 | - | - |
| Try Route Calculation | 0.56987 | 0.71698 | 0.14711 | - | - |
| Try to Optimize | 0.71698 | 1.237487 | 0.520507 | - | - |
| Execute SQL | 1.237487 | 9.091029 | 7.853542 | dn1.0 | select COUNT(*) as `_$COUNT$_rpda_0` from `sharding_two_node` LIMIT 100 |
| Fetch result | 9.091029 | 10.186782 | 1.095753 | dn1.0 | select COUNT(*) as `_$COUNT$_rpda_0` from `sharding_two_node` LIMIT 100 |
| Execute SQL | 1.237487 | 8.348635 | 7.111148 | dn2.0 | select COUNT(*) as `_$COUNT$_rpda_0` from `sharding_two_node` LIMIT 100 |
| Fetch result | 8.348635 | 9.342241 | 0.993606 | dn2.0 | select COUNT(*) as `_$COUNT$_rpda_0` from `sharding_two_node` LIMIT 100 |
| MERGE | 8.721543 | 10.289905 | 1.568362 | merge.1 | dn1.0; dn2.0 |
| ORDERED_GROUP | 8.726919 | 10.424309 | 1.69739 | ordered_group.1 | merge.1 |
| LIMIT | 9.020162 | 10.499574 | 1.479412 | limit.1 | ordered_group.1 |
| SHUFFLE_FIELD | 9.023584 | 10.501529 | 1.477945 | shuffle_field.1 | limit.1 |
| Write to Client | 9.072457 | 11.52055 | 2.448093 | - | - |
| Over All | 0.0 | 11.52055 | 11.52055 | - | - |
+-----------------------+-----------+-----------+--------------+-----------------+--------------------------------------------------------------------------+
14 rows in set (0.03 sec)
7. 子查询的trace结果举例
mysql> select count(*) from sharding_two_node where id =(select id from sharding_two_node where id=1);
+----------+
| COUNT(*) |
+----------+
| 1 |
+----------+
1 row in set (0.03 sec)
mysql> show trace;
+-----------------------+-----------+-----------+--------------+--------------------+-------------------------------------------------------------------------------------------------------------------+
| OPERATION | START(ms) | END(ms) | DURATION(ms) | SHARDING_NODE | SQL/REF |
+-----------------------+-----------+-----------+--------------+--------------------+-------------------------------------------------------------------------------------------------------------------+
| Read SQL | 0.0 | 0.063047 | 0.063047 | - | - |
| Parse SQL | 0.063047 | 0.491182 | 0.428135 | - | - |
| Try Route Calculation | 0.491182 | 0.799576 | 0.308394 | - | - |
| Try to Optimize | 0.799576 | 2.347412 | 1.547836 | - | - |
| Execute SQL | 2.347412 | 11.183808 | 8.836396 | dn1.0 | select `sharding_two_node`.`id` as `autoalias_scalar` from `sharding_two_node` where id = 1 LIMIT 2 |
| Fetch result | 11.183808 | 12.360691 | 1.176883 | dn1.0 | select `sharding_two_node`.`id` as `autoalias_scalar` from `sharding_two_node` where id = 1 LIMIT 2 |
| MERGE | 11.889546 | 12.436445 | 0.546899 | merge.1 | dn1.0 |
| LIMIT | 11.894923 | 12.483364 | 0.588441 | limit.1 | merge.1 |
| SHUFFLE_FIELD | 11.896389 | 12.48483 | 0.588441 | shuffle_field.1 | limit.1 |
| SCALAR_SUB_QUERY | 12.038123 | 12.485808 | 0.447685 | scalar_sub_query.1 | shuffle_field.1 |
| Generate New Query | 12.485808 | 13.824463 | 1.338655 | - | - |
| Execute SQL | 13.824463 | 26.749647 | 12.925184 | dn1.1 | scalar_sub_query.1; select COUNT(*) as `_$COUNT$_rpda_0` from `sharding_two_node` where sharding_two_node.id = 1 |
| Fetch result | 26.685134 | 28.753476 | 2.068342 | dn1.1 | scalar_sub_query.1; select COUNT(*) as `_$COUNT$_rpda_0` from `sharding_two_node` where sharding_two_node.id = 1 |
| MERGE | 26.954918 | 29.091683 | 2.136765 | merge.2 | dn1.1 |
| ORDERED_GROUP | 26.977889 | 29.563316 | 2.585427 | ordered_group.1 | merge.2 |
| SHUFFLE_FIELD | 27.568285 | 29.567226 | 1.998941 | shuffle_field.2 | ordered_group.1 |
| Write to Client | 27.72517 | 30.014911 | 2.289741 | - | - |
| Over All | 0.0 | 30.014911 | 30.014911 | - | - |
+-----------------------+-----------+-----------+--------------+--------------------+-------------------------------------------------------------------------------------------------------------------+
18 rows in set (0.01 sec)