经常碰到一个性能不佳SQL，进程要执行很久才能出来，想优化但是又不知道时间被浪费在哪里了。好容易X度到一个叫10046的可以追踪SQL的过程发现这东西出来根本看不懂。无奈之下使用怪怪的sqlplus里的set autotrace的stat看过程，无奈执行计划出来的都是不带时间和细节的。这可怎么办？看v$视图？不会用啊！！！！
有没有简单点的方式帮我们找到时间浪费在哪里了？有的。
v$视图中有个叫做V$SQL_MONITOR这个视图里记录了实际执行超过5秒钟的SQL内容。后面有很多列记录了很多有用的信息，例如SQL是否完成，执行时间，结束时间，执行时间等等。配合dbms_sqltune包。
笔者使用sh用户写了一个SQL
SELECT
prod_name, prod_desc ,count(*)
FROM
sh.costs a
JOIN sh.SALES b ON
a.PROD_ID = b.PROD_ID
JOIN sh.PRODUCTS c ON
a.PROD_ID = c.PROD_ID
WHERE to_char(a.TIME_ID,'yyyymmdd') LIKE '2016%'
or prod_name LIKE '%E%d'
OR prod_desc LIKE '%A%'
GROUP BY prod_name, prod_desc, a.TIME_ID
该SQL执行了1分53秒秒后才出结果。我们可以在v$sql_monitor中看到结果。（这里只是展示了部分信息）
|STATUS |PROGRAM |LAST_REFRESH_TIME | SQL_ID |IS_FULL_SQLTEXT|ELAPSED_TIME |
|DONE(FIRST N ROWS) |oracle@hp(M002) |2016-12-19 20:13:27| f6cz4n8y72xdc |Y |5534603 |
|DONE(ALL ROWS) |sqlplus@hp(TNS V1-V3) |2016-12-19 20:33:59| 1z0atyvua4xzv |Y |5474013 |
|DONE |sqlplus@hp(TNS V1-V3) |2016-12-19 20:40:54| 5s0s9ug4k3rcb |Y |5993330 |
|DONE |oracle@hp(J000) |2016-12-19 20:14:36| 6gvch1xu9ca3g |Y |9474032 |
|DONE |sqlplus@hp(TNS V1-V3) |2016-12-19 20:39:50| 90urupv3cmjmq |Y |68319089 |
|DONE(FIRST N ROWS) |DBeaver 3.7.8 |2016-12-19 21:42:26| 2rz47q4mqwtzj |Y |113424265 |
|DONE |sqlplus@hp(TNS V1-V3) |2016-12-19 20:38:19| 44pgaj5vdubxy |Y |316443454 |
我们可以看到很多内容，包括了很多物理读cpu时间等。但是这种可读性并不高。
我们可以使用
包配合的分析sql问题。
笔者的sql_id是2rz47q4mqwtzj，而且我希望看到最全的信息。
所以我的
可以这样写：
SELECT dbms_sqltune.REPORT_SQL_MONITOR(
sql_id=>'2rz47q4mqwtzj',
report_level=>'ALL',
TYPE=>'TEXT')
FROM dual ；
很快地数据库返回了一个clob类型内容。
SQL Monitoring Report
SQL Text
------------------------------
SELECT prod_name, prod_desc ,count(*) FROM sh.costs a JOIN sh.SALES b ON a.PROD_ID = b.PROD_ID JOIN sh.PRODUCTS c ON a.PROD_ID = c.PROD_ID WHERE to_char(a.TIME_ID,'yyyymmdd') LIKE '2016%' or prod_name LIKE '%E%d' OR prod_desc LIKE '%A%' GROUP BY prod_name, prod_desc, a.TIME_ID
Global Information
------------------------------
Status : DONE (FIRST N ROWS)
Instance ID : 1
Session : SYS (143:55)
SQL ID : 2rz47q4mqwtzj
SQL Execution ID : 16777216
Execution Started : 12/19/2016 21:40:33
First Refresh Time : 12/19/2016 21:40:39
Last Refresh Time : 12/19/2016 21:42:26
Duration : 113s
Module/Action : DBeaver 3.7.8/-
Service : YC
Program : DBeaver 3.7.8
Fetch Calls : 20
Global Stats
| Elapsed | Cpu | IO | Other | Fetch | Buffer | Read | Read |
| Time(s) | Time(s) | Waits(s) | Waits(s) | Calls | Gets | Reqs | Bytes |
| 113 | 113 | 0.00 | 0.69 | 20 | 310 | 16 | 2MB |
SQL Plan Monitoring Details (Plan Hash Value=4266705283)
| Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Mem | Activity | Activity Detail |
| | | | (Estim) | | Active(s) | Active | | (Actual) | (Max) | (%) | (# samples) |
| 0 | SELECT STATEMENT | | | | 108 | +6 | 1 | 200 | | | |
| 1 | HASH GROUP BY | | 4M | 2M | 113 | +1 | 1 | 200 | 21M | 76.11 | Cpu (86) |
| 2 | HASH JOIN | | 149M | 574 | 112 | +2 | 1 | 239M | 3M | 23.89 | Cpu (27) |
| 3 | HASH JOIN | | 11711 | 140 | 1 | +6 | 1 | 15384 | 1M | | |
| 4 | TABLE ACCESS FULL | PRODUCTS | 72 | 3 | 1 | +6 | 1 | 72 | | | |
| 5 | PARTITION RANGE ALL | | 82112 | 136 | 1 | +6 | 1 | 82112 | | | |
| 6 | TABLE ACCESS FULL | COSTS | 82112 | 136 | 1 | +6 | 28 | 82112 | | | |
| 7 | PARTITION RANGE ALL | | 919K | 29 | 108 | +6 | 1 | 919K | | | |
| 8 | BITMAP CONVERSION TO ROWIDS | | 919K | 29 | 108 | +6 | 28 | 919K | | | |
| 9 | BITMAP INDEX FAST FULL SCAN | SALES_PROD_BIX | | | 108 | +6 | 28 | 1074 | | | |
Global Stats中明确标明了各个重要参数使用了多少时间。
可以看到笔者这个sql时间主要浪费在cpu上。实际上IO上并没有使用太多时间。
总共读取数据量才2MB。也谈不上太大。
从SQL Plan Monitoring Details下面的执行计划上看到CPU在hash join上使用了不少的资源去解决筛选数据。
Rows列干脆就分成2个，一个是预测，另一个是实际值。
其实有经验的SQL人就知道，这个SQL的问题在于语句，而不是数据读取上的问题。
中国OCM之家
专注数据 共现梦想
QQ群：554334183
