关于奇怪的并行进程分析(三)

在前两篇的基础上，对于一个环境中存在的奇怪并行进程问题进行了初步的分析。
初步排除了是通过scheduler的job运行导致的，一方面因为运行的时间会有延迟，甚至有很大的差别。所以分析和排查按照scheduler的时间点没有办法抓到任何规律。
排除了scheduler的影响之后，在分析ash之后无果，最后无奈使用了自定义脚本来排查问题。当然这个也确实需要点时间。
通过脚本跟踪的方式还是针对性要强一些，有些明细信息在ash报告中也体现不到，比如启用了多少的并行进程，那些语句走了大量的并行等等。
查看今天早晨的日志，发现竟然还有SYS的用户在做并行查询，先来说说这个问题。
抓取到的日志信息如下：                                 
 17      19257 SYS        statdb96.cyou.com    oracle@statdb96.test.com (P013)  oracle     INACTIVE 2015-09-02 02:03:01  5vf4b6p4v79rm ENABLED    DISABLED   ENABLED
 29      64027 SYS        statdb96.cyou.com    oracle@statdb96.test.com (P056)  oracle     INACTIVE 2015-09-02 02:03:01  5vf4b6p4v79rm ENABLED    DISABLED   ENABLED
可以读取到SYS在运行sql_id 为 5vf4b6p4v79rm  的sql语句，而且走了并行，我们来看看这个语句到底是怎么样的。
因为之前通过v$sql,dba_sql_hist的方式去查找parallel相关的语句，也没有找到让人信服的sql语句，这种守株待兔的方式得到的语句还是值得信任的。
语句内容如下：
SELECT SERV_GROUP, CN_GUID, MAX(USER_CLASS) MCLASS, MAX(END_TIME) LASTTIME, MIN(END_TIME) FIRSTTIME
FROM TESTUSER.TEST_BILLDETAIL WHERE END_TIME >= :B2 AND END_TIME < :B1 AND CN_GUID > 0 GROUP BY SERV_GROUP,CN_GUID

这个语句中没有任何的并行hint，但是确确实实走了并行，而且并行度还很高。
查看一下执行计划,发现一个很明显的全表扫描。这个表的数据量过亿，这个全表扫描的代价还是很高的。
-------------------------------------------------------------------
| Id  | Operation                | Name           | Rows  | Bytes |
-------------------------------------------------------------------
|   0 | SELECT STATEMENT         |                |  1186K|    30M|
|*  1 |  PX COORDINATOR          |                |       |       |
|   2 |   PX SEND QC (RANDOM)    | :TQ10001       |  1186K|    30M|
|   3 |    HASH GROUP BY         |                |  1186K|    30M|
|   4 |     PX RECEIVE           |                |  1186K|    30M|
|   5 |      PX SEND HASH        | :TQ10000       |  1186K|    30M|
|*  6 |       FILTER             |                |       |       |
|   7 |        PX BLOCK ITERATOR |                |  1186K|    30M|
|*  8 |         TABLE ACCESS FULL| TEST_BILLDETAIL |  1186K|    30M|
-------------------------------------------------------------------

但是查看语句，也不是一个很复杂的语句，我们来看看为什么走了全表扫描，而怎么没有考虑到索引扫描。
INDEX_NAME                     TABLESPACE INDEX_TYPE UNIQUENES PAR COLUMN_LIST   
------------------------------ ---------- ---------- --------- --- --------------
IND_TEST_BILLDETAIL_CN                     NORMAL     NONUNIQUE YES CN            
IND_TEST_BILLDETAIL_END_TIME               NORMAL     NONUNIQUE YES END_TIME      

这个时候可以很i明显看到有一个索引是在字段END_TIME上的，所以说索引确确实实在哪儿，但是查询却压根没有走索引，而走了一个基于并行的圈全表扫描。
我们来看看索引的情况，这个索引是个分区索引，所以可以查看选择性的查看一部分索引信息。
INDEX_NAME           PAR_NAME          PAR_POS STATUS   
-------------------- --------------- ---------- ------- -------- 
IND_TEST_BILLDETAIL_CN TEST_BILLDETAIL_ 20091201       1 UNUSABLE 

IND_TEST_BILLDETAIL_CN TEST_BILLDETAIL_  20091202        1 UNUSABLE 
随便抓取了几条，仔细一看，发现有很多索引都是unusable状态了，这个时候问题似乎有了很大的转机，索引失效导致的索引扫描没有启用，而走了全表扫描。
而对于这个问题的修复相对来说就简单多了,重新做rebuild即可，为了不影响在线业务，可以做一个小的尝试，拿一个数据比较早的分区来做一个测试，看看rebuild index partition之后，是否索引会正常启用。
SQL> alter index ldj.IND_TEST_BILLDETAIL_END_TIME rebuild partition TEST_BILLDETAIL_20091201;
Index altered.   
这个时候验证语句就类似下面的形式,同时把并行的影响也取消了。
SELECT /*+no_parallel*/ SERV_GROUP, CN_GUID, MAX(USER_CLASS) MCLASS, MAX(END_TIME) LASTTIME, MIN(END_TIME) FIRSTTIME
    FROM LDJ.SWD_BILLDETAIL partition(TEST_BILLDETAIL_20091201) WHERE END_TIME >= :B2 AND END_TIME < :B1 AND CN_GUID > 0 GROUP BY SERV_GROUP,CN_GUID
rebuild index partition之前的执行计划如下：
-------------------------------------------------------------------
| Id  | Operation                | Name           | Rows  | Bytes |
-------------------------------------------------------------------
|   0 | SELECT STATEMENT         |                |    57 |  1197 |
|   1 |  HASH GROUP BY           |                |    57 |  1197 |
|*  2 |   FILTER                 |                |       |       |
|   3 |    PARTITION RANGE SINGLE|                |    57 |  1197 |
|*  4 |     TABLE ACCESS FULL    | TEST_BILLDETAIL |    57 |  1197 |
-------------------------------------------------------------------

rebuild index partition之后的 执行计划如下：
--------------------------------------------------------------------------------------------
| Id  | Operation                            | Name                        | Rows  | Bytes |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                     |                             |    57 |  1197 |
|   1 |  HASH GROUP BY                       |                             |    57 |  1197 |
|*  2 |   FILTER                             |                             |       |       |
|   3 |    PARTITION RANGE SINGLE            |                             |    57 |  1197 |
|*  4 |     TABLE ACCESS BY LOCAL INDEX ROWID| TEST_BILLDETAIL              |    57 |  1197 |
|*  5 |      INDEX RANGE SCAN                | IND_TEST_BILLDETAIL_END_TIME |   103 |       |
--------------------------------------------------------------------------------------------

可以看到索引是能够正常启用的，这个时候并行的影响就可以基本排除了。
最后我们来简单说一说这个并行。
SQL>select degree,table_name,owner from dba_tables where table_name='SWD_BILLDETAIL'
DEGREE               TABLE_NAME                     OWNER
-------------------- ------------------------------ ------------------------------
   DEFAULT           TEST_BILLDETAIL                 TESTDB
这种default的方式其实还有有些奇怪，如果要较真，会发现这个DEFAULT左边还是有一些空格的。
SQL> select degree from dba_tables where  degree= '   DEFAULT' and rownum<2;
DEGREE
--------------------
   DEFAULT
这个是在对象级开了并行，至于并行度的情况，还是和参数parallel_threads_per_cpu,cpu_count,parallel_execution_message_size有一些关系，我们先不细谈。
到此为止，我们发现了奇怪的并行问题其实和一个全表扫描相关，在这个基础上，继续分析发现索引没有启用，再进一步分析，发现对应的分区索引失效了。

这些问题都是一环套一环，缺一不可。
我们之前也分析过ASH报告中没有找到有效的信息， 至于这个问题，其实是人为操作误导。

这一点还是需要特别说明一下,可以看看下面的操作结果说明了什么
$ echo $ORACLE_SID
testdb1
$ sqlplus  testdba/testdba@testdb1
SQL> select count(*)from v$session;
COUNT(*)
----------
        39
SQL> conn / as sysdba
Connected.
SQL> select count(*)from v$session;
  COUNT(*)
----------
       165
SQL> show parameter uniq
NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_unique_name                       string      testdb96
这个奇怪问题的原因就在于我们使用原来的db_name连接到的实际上是备库，所以抓取的ash报告中没有任何的有效信息。
而这个问题的根源还是在于之前做了一次主从切换。结果从库变成了主库，使用的原来的Uniq_name也还是保留了原来的样子。tns这边也还是保留了原来的格式，结果在通过tns连接的时候就连接到了备库
当然事后也做了验证，发现ash在问题的时间点内抓取的报告还是很有效的，相关的问题sql都会抓取到。所以ASH报告还是很靠谱的。
通过这个案例我们可以看到对于一个很细小的问题进行深究会发现其实还是存在着一些潜在问题，问题的发生都是有原因的，性能的抖动也是有一些需要我们去关注的细节。
细节决定成败，说的也就是这个意思吧。