统计信息收集job导致cpu利用率100%

myownstars

OS: linux 2.6
DB: RAC两节点 10205
症状：
从上周五下午开始，第一节点的cpu资源消耗非常严重，TOP查看前几位的全是oracle进程，登陆数据库查看发现都在等待io slave wait且为并行进程，oradebug跟踪发现执行语句如下，应该是正在收集统计信息
select /*+ parallel(t,14) parallel_index(t,14) dbms_stats cursor_sharing_exact use_weak_name_resl dynamic_sampling(0) no_monitoring */ count(*),count(distinct "ID"),sum(sys_op_o
pnsize("ID")),count(distinct "TYPE"),sum(sys_op_opnsize("TYPE")),count(distinct "TASK_ID"),sum(sys_op_opnsize("TASK_ID")),count("ATTR1"),count(distinct "ATTR1"),sum(sys_op_opnsi
ze("ATTR1")),substrb(dump(min(substrb("ATTR1",1,32)),16,0,32),1,120),substrb(dump(max(substrb("ATTR1",1,32)),16,0,32),1,120),count("ATTR2"),count(distinct "ATTR2"),sum(sys_op_op
nsize("ATTR2")),substrb(dump(min(substrb("ATTR2",1,32)),16,0,32),1,120),substrb(dump(max(substrb("ATTR2",1,32)),16,0,32),1,120),count("ATTR3"),count(distinct "ATTR3"),sum(sys_op
_opnsize("ATTR3")),substrb(dump(min(substrb("ATTR3",1,32)),16,0,32),1,120),substrb(dump(max(substrb("ATTR3",1,32)),16,0,32),1,120),count(case when "ATTR4" is null then null else
1 end),sum(sys_op_opnsize("ATTR4")),count("ATTR5"),count(distinct "ATTR5"),sum(sys_op_opnsize("ATTR5")),substrb(dump(min(substrb("ATTR5",1,32)),16,0,32),1,120),substrb(dump(max
(substrb("ATTR5",1,32)),16,0,32),1,120),count(case when "OTHER" is null then null else 1 end),sum(sys_op_opnsize("OTHER")) from "SYS"."WRI$_ADV_OBJECTS" t

原本以为周末会自行结束，但是今早发现这些进程都还在，而且又涌现出一批新的并行进程同样在收集统计信息
$top
top - 04:17:39 up 37 days, 11:50,  7 users,  load average: 9.26, 9.45, 9.50
Tasks: 267 total,  11 running, 256 sleeping,   0 stopped,   0 zombie
Cpu(s): 85.0% us, 15.0% sy,  0.0% ni,  0.0% id,  0.0% wa,  0.0% hi,  0.0% si
Mem:  17517944k total, 16540076k used,   977868k free,  1375324k buffers
Swap:  2097144k total,    50704k used,  2046440k free, 12219404k cached
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
20357 oracle    25   0 6287m  23m  17m R 50.2  0.1   6158:39 oracle
20332 oracle    25   0 6287m  23m  17m R 49.8  0.1   6153:07 oracle
20344 oracle    25   0 6287m  23m  17m R 49.8  0.1   6159:54 oracle
20348 oracle    25   0 6287m  23m  17m R 49.8  0.1   6163:34 oracle
20340 oracle    25   0 6287m  23m  17m R 49.5  0.1   6157:51 oracle
20336 oracle    25   0 6287m  23m  17m R 48.5  0.1   6163:47 oracle
20292 oracle    25   0 6289m  40m  34m R 33.6  0.2   6157:23 oracle
20309 oracle    25   0 6289m  40m  34m R 33.6  0.2   6156:50 oracle
20315 oracle    25   0 6289m  23m  17m R 33.2  0.1   6162:44 oracle
29340 oracle    16   0 6286m  28m  24m S  1.0  0.2   0:00.03 oracle
7908 oracle    16   0  5504 1260  816 R  0.3  0.0   0:02.99 top                                                                                                        
20640 oracle    16   0 6284m  16m  13m S  0.3  0.1   0:15.70 oracle  

$ vmstat 2
procs -----------memory---------- ---swap-- -----io---- --system-- ----cpu----
r  b   swpd   free   buff  cache   si   so    bi    bo   in    cs us sy id wa
9  0  50704 946268 1375336 12219800    0    0  2080   588    1     1 37  7 53  3
9  0  50704 959348 1375336 12219800    0    0    34   121 1074  1750 85 15  0  0
9  0  50704 959396 1375336 12219800    0    0    42     1 1052  1711 85 15  0  0
9  0  50704 959588 1375336 12219800    0    0    34    43 1060  1723 85 15  0  0
9  0  50704 959404 1375336 12219800    0    0    90   139 1127  2973 84 16  0  0
9  1  50704 958844 1375336 12219800    0    0    34   235 1082  2168 83 17  0  0
9  0  50704 959100 1375336 12219800    0    0    42   319 1092  1999 84 16  0  0

Username     QC/Slave SlaveSet SID    Slave INS STATE    WAIT_EVENT                     QC SID QC INS Req. DOP Actual DOP
------------ -------- -------- ------ --------- -------- ------------------------------ ------ ------ -------- ----------
SYS          QC                464    3         WAIT     PX Deq: Execute Reply          464
- pz99      (Slave)  1        403    3         WAIT     PX Deq: Execution Msg          464    3             2          2
- pz99      (Slave)  1        483    4         WAIT     PX Deq: Execution Msg          464    3             2          2
- p041      (Slave)  2        452    3         WAIT     i/o slave wait                 474    4            14         14
- p047      (Slave)  2        453    3         WAIT     i/o slave wait                 474    4            14         14
- p050      (Slave)  2        443    3         WAIT     i/o slave wait                 498    4            14         14
- p056      (Slave)  2        447    3         WAIT     i/o slave wait                 498    4            14         14
- p066      (Slave)  2        440    3         WAIT     i/o slave wait                 498    4            14         14
- p064      (Slave)  2        439    3         WAIT     i/o slave wait                 498    4            14         14
- p062      (Slave)  2        438    3         WAIT     i/o slave wait                 498    4            14         14
- p058      (Slave)  2        444    3         WAIT     i/o slave wait                 498    4            14         14
- p060      (Slave)  2        437    3         WAIT     i/o slave wait                 498    4            14         14
SYS          QC                500    4         WAIT     PX Deq: Execute Reply          500
- p004      (Slave)  1        431    3         WAIT     PX Deq: Execution Msg          500    4            16         16
- p005      (Slave)  1        430    3         WAIT     PX Deq: Execution Msg          500    4            16         16
- p008      (Slave)  1        457    3         WAIT     PX Deq: Execution Msg          500    4            16         16
- p007      (Slave)  1        483    3         WAIT     PX Deq: Execution Msg          500    4            16         16
- p006      (Slave)  1        467    3         WAIT     PX Deq: Execution Msg          500    4            16         16
- p011      (Slave)  1        472    3         WAIT     PX Deq: Execution Msg          500    4            16         16
- p009      (Slave)  1        494    3         WAIT     PX Deq: Execution Msg          500    4            16         16
- p010      (Slave)  1        442    3         WAIT     PX Deq: Execution Msg          500    4            16         16
- p015      (Slave)  1        531    4         WAIT     PX Deq: Execution Msg          500    4            16         16
- p016      (Slave)  1        534    4         WAIT     PX Deq: Execution Msg          500    4            16         16
- p012      (Slave)  1        521    4         WAIT     PX Deq: Execution Msg          500    4            16         16
- p018      (Slave)  1        499    4         WAIT     PX Deq: Execution Msg          500    4            16         16
- p014      (Slave)  1        484    4         WAIT     PX Deq: Execution Msg          500    4            16         16
- p019      (Slave)  1        462    4         WAIT     PX Deq: Execution Msg          500    4            16         16
- p013      (Slave)  1        459    4         WAIT     PX Deq: Execution Msg          500    4            16         16
- p017      (Slave)  1        443    4         WAIT     PX Deq: Execution Msg          500    4            16         16
- p012      (Slave)  2        477    3         WAIT     PX Deq: Execution Msg          500    4            16         16
- p014      (Slave)  2        495    3         WAIT     PX Deq: Execution Msg          500    4            16         16
- p015      (Slave)  2        499    3         WAIT     PX Deq: Execution Msg          500    4            16         16
- p017      (Slave)  2        502    3         WAIT     PX Deq: Execution Msg          500    4            16         16
- p013      (Slave)  2        514    3         WAIT     PX Deq: Execution Msg          500    4            16         16
- p016      (Slave)  2        486    3         WAIT     PX Deq: Execution Msg          500    4            16         16
- p019      (Slave)  2        408    3         WAIT     PX Deq: Execution Msg          500    4            16         16
- p018      (Slave)  2        421    3         WAIT     PX Deq: Execution Msg          500    4            16         16
- p021      (Slave)  2        529    4         WAIT     PX Deq: Execution Msg          500    4            16         16
- p026      (Slave)  2        450    4         WAIT     i/o slave wait                 500    4            16         16
- p020      (Slave)  2        491    4         WAIT     PX Deq: Execution Msg          500    4            16         16
- p025      (Slave)  2        486    4         WAIT     PX Deq: Execution Msg          500    4            16         16
- p023      (Slave)  2        514    4         WAIT     PX Deq: Execution Msg          500    4            16         16
- p022      (Slave)  2        477    4         WAIT     PX Deq: Execution Msg          500    4            16         16
- p024      (Slave)  2        466    4         WAIT     PX Deq: Execution Msg          500    4            16         16
- p027      (Slave)  2        503    4         WAIT     PX Deq: Execution Msg          500    4            16         16
45 rows selected.

附件为hanganalyze/systemstate文件
请maclean和其他高手帮忙诊断一下，谢谢！

Maclean Liu(刘相兵

10.2.0.5 + Linux x86_64

SYS          QC                464    3  
SYS          QC                500    4  

coordinate 进程是 sid 464  和 sid 500

trace中未找到 sid 500的信息

sid 464  是  人为或脚本使用sqlplus 登录的session ,



    SO: 0x1dfa1b250, type: 4, owner: 0x1df6b5e20, flag: INIT/-/-/0x00
    (session) sid: 464 trans: (nil), creator: 0x1df6b5e20, flag: (41) USR/- -/-/-/-/-/-
              DID: 0001-0019-0007C5A6, short-term DID: 0001-0019-0007C5A7
              txn branch: (nil)
              oct: 0, prv: 0, sql: (nil), psql: 0x1c323d840, user: 0/SYS
    service name: SYS$USERS
    O/S info: user: oracle, term: pts/3, ospid: 12241, machine: semldslx5077
              program: sqlplus@semldslx5077 (TNS V1-V3)
    application name: sqlplus@semldslx5077 (TNS V1-V3), hash value=72071072
    last wait for 'SQL*Net message from client' wait_time=7.571451 sec, seconds since wait started=9
                driver id=62657100, #bytes=1, =0
                blocking sess=0x(nil) seq=220
    Dumping Session Wait History


应当是有人或者脚本 登录db ， 执行 exec  dbms_stats.gather_schema_stats('',degree=>16);  以16的并行度 收集信息的匿名块， 导致并行收集SYS 用户下的对象， 导致CPU使用率升高

登录用户使用DB本机的oracle账户

SQL> oradebug setmypid
Statement processed.
SQL> oradebug event 10046 trace name context forever,level 1;
Statement processed.
SQL> exec  dbms_stats.gather_schema_stats('',degree=>16);

PL/SQL procedure successfully completed.

SQL> oradebug tracefile_name;
/s01/admin/G10R25/udump/g10r25_ora_3684.trc


select /*+ no_parallel(t) no_parallel_index(t) dbms_stats cursor_sharing_exact use_weak_name_resl dynamic_sampling(0) no_monitoring */ count(*),sum(sys_op_opnsize("ID"
)),sum(sys_op_opnsize("TYPE")),sum(sys_op_opnsize("TASK_ID")),count("ATTR1"),count(distinct "ATTR1"),sum(sys_op_opnsize("ATTR1")),substrb(dump(min(substrb("ATTR1",1,32
)),16,0,32),1,120),substrb(dump(max(substrb("ATTR1",1,32)),16,0,32),1,120),count("ATTR2"),count(distinct "ATTR2"),sum(sys_op_opnsize("ATTR2")),substrb(dump(min(substrb
("ATTR2",1,32)),16,0,32),1,120),substrb(dump(max(substrb("ATTR2",1,32)),16,0,32),1,120),count("ATTR3"),count(distinct "ATTR3"),sum(sys_op_opnsize("ATTR3")),substrb(dum
p(min(substrb("ATTR3",1,32)),16,0,32),1,120),substrb(dump(max(substrb("ATTR3",1,32)),16,0,32),1,120),count(case when "ATTR4" is null then null else 1 end),sum(sys_op_o
pnsize("ATTR4")),count("ATTR5"),count(distinct "ATTR5"),sum(sys_op_opnsize("ATTR5")),substrb(dump(min(substrb("ATTR5",1,32)),16,0,32),1,120),substrb(dump(max(substrb("
ATTR5",1,32)),16,0,32),1,120),count(case when "OTHER" is null then null else 1 end),sum(sys_op_opnsize("OTHER")) from "SYS"."WRI$_ADV_OBJECTS" t

myownstars

多谢回复
但是这个数据库并不大，尤其是sys用户，查看dba_segments显示总计只有不到2G的大小；
却为何该job跑了将近3天仍不结束，且各个子进程都显示在执行
select /*+ no_parallel(t) no_parallel_index(t) dbms_stats cursor_sharing_exact use_weak_name_resl ............from "SYS"."WRI$_ADV_OBJECTS" t

即便是I/O吞吐再不济也应该执行完了，是否由相应BUG引起？

刚刚收工执行了一下，并行度16，不到10分钟就执行完毕了

jackyshen

AWR报告有么?请提供下正常时间的和非正常时间的