转载

备库报警邮件的分析案例（二)

在第一篇中分享了关于备库报警邮件的分析，发现很多问题都是一环扣一环.
起初是通过监控主库中的v$dataguard_status发现备库中可能存在一些问题，结果逐步分析，发现是由备库的crontab触发了备库的定时read-only和online状态，（即只读和应用日志，10gR2的环境），而这些关键信息都是从数据库的alert日志中发现的，但是问题还没有完，才刚刚开始，因为发现备库中竟然有ORA-1652: unable to extend temp segment by 128 in tablespace的错误，这在备库中着实是很奇怪的，备库在read-only状态时会有什么样的sql语句对于temp消耗如此之大？通过对比主备库发现，主库仅仅为32G，而备库却有近98G大小，而且从历史记录来看，这个错误一致存在，也算是一个历史遗留问题吧。
通过分析temp的空间占用情况，发现系统级的磁盘空间确实也不够了。目前只保留了20G左右，如果系统出现了大的业务抖动，这备库的空间使用是岌岌可危的。
在暂时没有办法去换取硬件的情况下，就可以考虑删除两个临时数据文件，但是这个时候就需要明白为什么备库要3个临时数据文件，这种使用是否合理，是不是哪里出了问题。
对于这个问题，自己也走了一点弯路，那就是通过ash的思路来分析。
在备库中抓取了问题时间段里的ash报告，发现下面两条sql貌似占有了一定的比例。
Top SQL Statements

SQL ID	Planhash	% Activity	Event	% Event	SQL Text
57j9uu7c9681a	672161835	34.48	db file sequential read	27.59	SELECT * FROM TEST_CN_BIND WHERE CN...
			CPU + Wait for CPU	6.90
2w4d3aa19719s	935831560	17.24	db file sequential read	15.52	SELECT CN_MASTER, PASSWD, BIND...

top1的语句为
SELECT * FROM TEST_CN_BIND WHERE CN=:1 AND CN_TYPE IN(1, 2, 3) AND ENAABLED='Y' ORDER BY CN_TYPE
执行计划为：
Execution Plan
-----------------------------------------------------------------------------------------------
| Id | Operation                    | Name           | Rows | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                |       |       |     3 (100)|          |
|   1 | SORT ORDER BY               |                |     1 |    43 |     3 (34)| 00:00:01 |
|   2 |   TABLE ACCESS BY INDEX ROWID| TEST_CN_BIN    |     1 |    43 |     2   (0)| 00:00:01 |
|   3 |    INDEX RANGE SCAN          | IDX_CN_BIND_CN |     1 |       |     1   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------
通过这个也着实看不出有什么问题了，top 2的语句也是类似的情况。
这个时候就有些迷茫了，到底是什么原因导致了temp的过度使用。
这个问题回过头来看，首先要明白什么操作可能会消耗大量的temp，使用temp的场景有下面几种
- 索引创建或重创建.
- ORDER BY or GROUP BY
- DISTINCT 操作.
- UNION & INTERSECT & MINUS 等集合运算
- Sort-Merge joins.
- Analyze 操作
--其它异常
那么到底可能是什么原因呢，查看了所有的top sql发现只有top1的语句含有order by的字样，但是通过执行计划来分析，却实在分析不出来更多的数据，因为确实走了索引，这个索引列重复值极低，所以order by的代价非常小，尽管执行频率极高，有大概百万的调用次数
Stat Name                 Statement   Per Execution % Snap
------------------------------------ -------------- -------
Elapsed Time (ms)            760,955            0.8    40.6
CPU Time (ms)                 80,327            0.1    11.7
Executions                 1,007,536            N/A     N/A
Buffer Gets                4,223,066            4.2    52.4
Disk Reads                   110,754            0.1    45.3
Parse Calls                1,007,396            1.0    40.0
Rows                         185,860            0.2     N/A
User I/O Wait Time (ms)      684,686            N/A     N/A
Cluster Wait Time (ms)             0            N/A     N/A
Application Wait Time (ms)         0            N/A     N/A
Concurrency Wait Time (ms)         0            N/A     N/A
Invalidations                      0            N/A     N/A
Version Count                      8            N/A     N/A
Sharable Mem(KB)                 127            N/A     N/A
所以看着这个报告，让人着实摸不着头脑，这个时候也不能风风火火开始调优，既然自己都说不通自己，那么到底是怎么消耗的temp,这些还是需要找到靠谱的理由来。
而temp的使用情况是一个动态的过程，所以直接通过历史视图等等是无从知晓的。
我们可以使用手工监控的方式来做。
第一个脚本为：
语句为check_temp.sh
##check_temp.sh
function get_temp_usage
{
sqlplus -s / as sysdba < set time on
set pages 100
set linesize 200
col sysdate format a10
col username format a15
col sid format 9999
col serial# format 99999
col blocks format 99999999
col sql_text format a70
set feedback off
select systimestamp from dual;
set feedback on
SELECT sysdate,a.username, a.sid, a.serial#, a.osuser, b.blocks, c.sql_text
FROM v/$session a, v/$sort_usage b, v/$sqlarea c
WHERE b.tablespace = 'TEMP'
and a.saddr = b.session_addr
AND c.address= a.sql_address
AND c.hash_value = a.sql_hash_value
AND b.blocks*8192 > 0
ORDER BY b.tablespace, b.blocks;
EOF
}
get_temp_usage

第二个就是个种子程序来调用，给定10秒的轮询。
$ cat tmp.sh
for i in {1..36000}
do
sh check_temp.sh >> check_temp.log
sleep 10
done
这种守株待兔的方式看起来不是很灵活，但是着实有效。
昨晚写好之后来看，早上收网就发现有收获了。发现在早晨的特定时间段里，有两个session在运行同样的sql语句，语句的temp使用起初不大。都是4000多个block,大概是31M
SYSTIMESTAMP
-----------------------------------------------------
11-NOV-15 06.00.21.907858 AM +08:00

SYSDATE    USERNAME     SID SERIAL# OSUSER      BLOCKS SQL_TEXT
---------- ---------- ----- ------- ------------------ ----------------------------------------------------------------------
2015-11-11 TEST_SHINK 6553   47693 webadmin      4352 select c.cn as cn, c.uin as uin from (select cn from test_cn_bind where ena
06:00:21                                              bled='Y' group by cn having count(cn)>1) t, cn_bind c where t.cn = c.c
                                                       n and c.enabled='Y' order by cn

2015-11-11 TEST_SHINK 6533   60000 webadmin      4480 select c.cn as cn, c.uin as uin from (select cn from test_cn_bind where ena
06:00:21                                                   bled='Y' group by cn having count(cn)>1) t, cn_bind c where t.cn = c.c
                                                            n and c.enabled='Y' order by cn

但是继续往下看，就发现这个问题就开始突出了。
SYSDATE    USERNAME          SID SERIAL# OSUSER    BLOCKS SQL_TEXT
---------- --------------- ----- ------- -------- ------- ----------------------------------------------------------------------
2015-11-11 TEST_SHINK       6553   47693 webadmin 3302400 select c.cn as cn, c.uin as uin from (select cn from test_cn_bind where ena
06:57:37                                                 bled='Y' group by cn having count(cn)>1) t, test_cn_bind c where t.cn = c.c
                                                          n and c.enabled='Y' order by cn

2015-11-11 TEST_SHINK       6533   60000 webadmin 3302400 select c.cn as cn, c.uin as uin from (select cn from test_cn_bind where ena
06:57:37                                                 bled='Y' group by cn having count(cn)>1) t, test_cn_bind c where t.cn = c.c
                                                          n and c.enabled='Y' order by cn
按照这个量级和使用情况，一条语句需要消耗的temp大小为近26G,两条sql占用的就是52G
SQL> select 3302400*8192/1024/1024 size_MB from dual;
   SIZE_MB
----------
     25800
听起来似乎还是有余地，不是配置了98G的temp空间吗，应该还够用，但是继续往下看就发现后面还会有其它的session进来。最多的时候差不多8个，这样计算的话，98G的空间也是不够的。
来看看这个语句的资源消耗，预估是近18G的temp使用。
----------------------------------------------------------------------------------
| Id | Operation              | Name       | Rows | Bytes |TempSpc| Cost (%CPU)|
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT       |            |    29M| 1654M|       | 5361K (4)|
|   1 | SORT ORDER BY         |            |    29M| 1654M| 2032M| 5361K (4)|
|* 2 |   HASH JOIN            |            |    29M| 1654M| 1037M| 4941K (4)|
|   3 |    VIEW                |            |    29M|   700M|       | 2696K (5)|
|* 4 |     FILTER             |            |       |       |       |            |
|   5 |      HASH GROUP BY     |            |    29M|   756M|    19G| 2696K (5)|
|* 6 |       TABLE ACCESS FULL|TEST_CN_BIND|   587M|    14G|       |   898K (5)|
|* 7 |    TABLE ACCESS FULL   |TEST_CN_BIND|   587M|    18G|       |   898K (5)|
----------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("T"."CN"="C"."CN")
   4 - filter(COUNT(*)>1)
   6 - filter("ENABLED"='Y')
   7 - filter("C"."ENABLED"='Y')
有同事提问是否这个语句存在并行的可能性，显然是不会的，一来从执行计划中没有任何痕迹，二来如果是并行，session应该同时被监控出来，而不是后面逐步多起来。
这条语句如果细看还是存在一定的问题，这么大的表引用了两次同一个大表，其实完全可以改写为更简单的形式
select c.cn as cn,c.uin from test_cn_bind c where enabled='Y' group by c.cn,c.uin having count(c.cn) >1;
当然这个时候在备库中还是可以考虑使用并行资源的。
可能到这个时候问题的分析就到此为止了，就可以质问开发的同学，为什么写出这么消耗资源的语句来，然后把他们痛批一顿，其实还真不是这样，而且这样也没有找到根本的原因，为什么需要这个查询，这是基于什么样的需求等等，其实还有很多需要改进的东西，比如在10g版本中备库的ash其实就是主库的这些信息，在11g以后就可以独立查看备库的ash了。在下一个章节继续再说这个问题的由来和改进。

正文到此结束