Oracle 性能极具下降,CPU消耗近100%，求高人解决！！

Question

当前oracle10运行在solaris服务器上，客户端启动5个远程数据库连接，
每个连接，都不停地对数据库中的一张表进行查询，更新（无删除）操作，
也就是说，表中的数据库量无增减，始终保持在20万条左右。开始时，数据库运行良好，CPU消耗为50%左右，但运行了一天，发现CPU突然上升为100%
此时，性能明显下降，下面是我做的statpack,请高人参考，万分感谢！！！
STATSPACK report forDatabase                            DB Id
Instance                         Inst Num
Startup Time                     Release
RAC
~~~~~~~~                         -----------
------------                     --------
---------------                  -----------
---
                                  3292398161 uep                 1
10-Nov-08 08:50 10.2.0.2.0  NOHost  Name:   ZTECLUSTER1      Num CPUs:    4
Phys Memory (MB):    2,040
~~~~Snapshot       Snap Id     Snap Time      Sessions Curs/Sess Comment
~~~~~~~~    ---------- ------------------ -------- --------- -------------------
Begin Snap:          3 10-Nov-08 09:25:44       21       3.9
  End Snap:          4 10-Nov-08 09:27:39       21       6.1
   Elapsed:                1.92 (mins)Cache Sizes                       Begin        End
~~~~~~~~~~~                  ---------- ----------
               Buffer Cache:       848M             Std Block Size:         8K
           Shared Pool Size:       272M
     Log Buffer:                    14,899K

Answer 1

Load Profile                            Per Second       Per Transaction
~~~~~~~~~~~~                       ---------------       ---------------
                  Redo size:              4,912.28             80,701.71
              Logical reads:             31,712.52            520,991.43
              Block changes:                  7.70                126.57
             Physical reads:                  2.63                 43.14
            Physical writes:                  0.08                  1.29
                 User calls:                140.34              2,305.57
                     Parses:                 27.05                444.43
                Hard parses:                  0.63                 10.29
                      Sorts:                  5.04                 82.86
                     Logons:                  0.02                  0.29
                   Executes:                 37.90                622.57
               Transactions:                  0.06  % Blocks changed per Read:    0.02    Recursive Call %:                61.72
 Rollback per transaction %:    0.00       Rows per Sort:                13.51Instance Efficiency Percentages
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:  100.00       Redo NoWait %:  100.00
            Buffer  Hit   %:   99.99    In-memory Sort %:  100.00
            Library Hit   %:   92.22        Soft Parse %:   97.69
         Execute to Parse %:   28.61         Latch Hit %:   99.99
Parse CPU to Parse Elapsd %:   60.38     % Non-Parse CPU:   99.93 Shared Pool Statistics        Begin   End
                               ------  ------
             Memory Usage %:   28.59   29.72
    % SQL with executions>1:   55.82   62.25
  % Memory for SQL w/exec>1:   66.34   71.83Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
CPU time                                                       438          99.2
db file sequential read                            163           1      6     .2
control file parallel write                         38           1     21     .2
log file parallel write                             11           1     59     .1
db file scattered read                              36           1     17     .1
          -------------------------------------------------------------
Host CPU  (CPUs: 4)
~~~~~~~~              Load Average
                      Begin     End      User  System    Idle     WIO     WCPU
                    ------- -------   ------- ------- ------- ------- --------
                                    5.55    5.59
                                   97.47    1.30    1.22    0.00   40.26Instance CPU
~~~~~~~~~~~~
              % of total CPU for Instance:
  95.99
              % of busy  CPU for Instance:
  97.18
  %DB time waiting for CPU - Resource Mgr:
Memory Statistics                       Begin          End
~~~~~~~~~~~~~~~~~                ------------ ------------
                  Host Mem (MB):      2,039.5      2,039.5
                   SGA use (MB):      1,168.0      1,168.0
                   PGA use (MB):         44.0         43.8
    % Host Mem used for SGA+PGA:         59.4         59.4
          -------------------------------------------------------------Time Model System Stats  DB/Inst: UEP/uep  Snaps: 3-4
-> Ordered by % of DB time desc, Statistic nameStatistic                                       Time (s) % of DB time
----------------------------------- -------------------- ------------
sql execute elapsed time                           470.3         99.8
DB CPU                                             429.0         91.0
parse time elapsed                                   0.8           .2
hard parse elapsed time                              0.7           .2
PL/SQL execution elapsed time                        0.0           .0
repeated bind elapsed time                           0.0           .0
DB time                                            471.3
background elapsed time                              1.6
background cpu time                                  0.2
          -------------------------------------------------------------
Wait Events  DB/Inst: UEP/uep  Snaps: 3-4
-> s - second, cs - centisecond,  ms - millisecond, us - microsecond
-> %Timeouts:  value of 0 indicates value was < .5%.  Value of null is truly 0
-> Only events with Total Wait Time (s) >= .001 are shown
-> ordered by Total Wait Time desc, Waits desc (idle events last)                                                                    Avg
                                                %Time Total Wait   wait    Waits
Event                                    Waits  -outs   Time (s)   (ms)     /txn
--------------------------------- ------------ ------ ---------- ------ --------
db file sequential read                    163      0          1      6     23.3
control file parallel write                 38      0          1     21      5.4
log file parallel write                     11      0          1     59      1.6
db file scattered read                      36      0          1     17      5.1
log file sync                                4      0          0     88      0.6
db file parallel write                       9      0          0      6      1.3
control file sequential read               193      0          0      0     27.6
latch: cache buffers chains                  2      0          0      2      0.3
SQL*Net message from client             16,137      0        181     11  2,305.3
virtual circuit status                       4    100        117  29304      0.6
Streams AQ: qmn slave idle wait              4      0        109  27353      0.6
Streams AQ: qmn coordinator idle             8     50        109  13677      1.1
jobq slave wait                             37     95        109   2935      5.3
SQL*Net message to client               16,137      0          0      0  2,305.3
          -------------------------------------------------------------
Background Wait Events  DB/Inst: UEP/uep  Snaps: 3-4
-> %Timeouts:  value of 0 indicates value was < .5%.  Value of null is truly 0
-> Only events with Total Wait Time (s) >= .001 are shown
-> ordered by Total Wait Time desc, Waits desc (idle events last)

Answer 2

Event                                    Waits  -outs   Time (s)   (ms)     /txn
--------------------------------- ------------ ------ ---------- ------ --------
control file parallel write                 38      0          1     21      5.4
log file parallel write                     11      0          1     59      1.6
db file parallel write                       9      0          0      6      1.3
rdbms ipc message                          368     98        885   2404     52.6
pmon timer                                  38    100        112   2939      5.4
Streams AQ: qmn slave idle wait              4      0        109  27353      0.6
Streams AQ: qmn coordinator idle             8     50        109  13677      1.1
          -------------------------------------------------------------
Wait Event Histogram  DB/Inst: UEP/uep  Snaps: 3-4
-> Total Waits - units: K is 1000, M is 1000000, G is 1000000000
-> % of Waits - column heading: <=1s is truly <1024ms, >1s is truly >=1024ms
-> % of Waits - value: .0 indicates value was <.05%, null is truly 0
-> Ordered by Event (idle events last)                           Total ----------------- % of Waits ------------------
Event                      Waits  <1ms  <2ms  <4ms  <8ms <16ms <32ms  <=1s   >1s
-------------------------- ----- ----- ----- ----- ----- ----- ----- ----- -----
control file parallel writ   38                            7.9  89.5   2.6
control file sequential re  193   97.9               1.6    .5
db file parallel write        9         11.1  11.1  55.6  22.2
db file scattered read       35   22.9  11.4         8.6  17.1  28.6  11.4
db file sequential read     162   35.8   1.9  10.5  30.2   8.6  11.7   1.2
latch: cache buffers chain    2   50.0        50.0
log file parallel write      11    9.1         9.1  45.5   9.1  18.2   9.1
log file sync                 4                     25.0  50.0        25.0
SQL*Net message from clien   16K  89.2   1.0    .8   1.1   2.9   1.0   4.0    .0
SQL*Net message to client    16K 100.0                            .0
Streams AQ: qmn coordinato    8   50.0                                      50.0
Streams AQ: qmn slave idle    4                                            100.0
dispatcher timer              2                                            100.0
jobq slave wait              37                                            100.0
pmon timer                   38                                            100.0
rdbms ipc message           368     .8    .5                          31.0  67.7
virtual circuit status        4                                            100.0
          -------------------------------------------------------------SQL ordered by CPU  DB/Inst: UEP/uep  Snaps: 3-4
-> Resources reported for PL/SQL code includes the resources used by all SQL
   statements called by the code.
-> Total DB CPU (s):             429
-> Captured SQL accounts for   99.1% of Total DB CPU
-> SQL reported below exceeded  1.0% of Total DB CPU    CPU                  CPU per             Elapsd                     Old
  Time (s)   Executions  Exec (s)  %Total   Time (s)    Buffer Gets  Hash Value
---------- ------------ ---------- ------ ---------- --------------- ----------
    423.42        1,323       0.32   98.7     462.84       3,585,450 3016263992
Module: JDBC Thin Client
select pkgName from ZXAN_IPTVPKGTABLE where neId = :1 and SYS_OP
_VECBIT(userRecvPortList, LENGTH(userRecvPortList) * 4 - :2) = 1
          -------------------------------------------------------------
SQL ordered by Elapsed  DB/Inst: UEP/uep  Snaps: 3-4
-> Resources reported for PL/SQL code includes the resources used by all SQL
   statements called by the code.
-> Total DB Time (s):             471
-> Captured SQL accounts for   98.9% of Total DB Time
-> SQL reported below exceeded  1.0% of Total DB Time  Elapsed                Elap per            CPU                        Old
  Time (s)   Executions  Exec (s)  %Total   Time (s)  Physical Reads Hash Value
---------- ------------ ---------- ------ ---------- --------------- ----------
    462.84        1,323       0.35   98.2     423.42               0 3016263992
Module: JDBC Thin Client
select pkgName from ZXAN_IPTVPKGTABLE where neId = :1 and SYS_OP
_VECBIT(userRecvPortList, LENGTH(userRecvPortList) * 4 - :2) = 1
          -------------------------------------------------------------
SQL ordered by Gets  DB/Inst: UEP/uep  Snaps: 3-4
-> Resources reported for PL/SQL code includes the resources used by all SQL
   statements called by the code.
-> End Buffer Gets Threshold:     10000 Total Buffer Gets:       3,646,940
-> Captured SQL accounts for   98.4% of Total Buffer Gets
-> SQL reported below exceeded  1.0% of Total Buffer Gets                                                     CPU      Elapsd     Old
  Buffer Gets    Executions  Gets per Exec  %Total Time (s)  Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
      3,585,450        1,323        2,710.1   98.3   423.42    462.84 3016263992
Module: JDBC Thin Client
select pkgName from ZXAN_IPTVPKGTABLE where neId = :1 and SYS_OP
_VECBIT(userRecvPortList, LENGTH(userRecvPortList) * 4 - :2) = 1
          -------------------------------------------------------------
SQL ordered by Reads  DB/Inst: UEP/uep  Snaps: 3-4
-> End Disk Reads Threshold:      1000  Total Disk Reads:             302
-> Captured SQL accounts for    0.0% of Total Disk Reads
-> SQL reported below exceeded  1.0% of Total Disk Reads                                                     CPU      Elapsd     Old
 Physical Reads  Executions  Reads per Exec %Total Time (s)  Time (s) Hash Value
--------------- ------------ -------------- ------ -------- --------- ----------
            183            1          183.0   60.6     1.49      2.93 2522684317
Module: SQL*Plus
BEGIN statspack.snap; END;          -------------------------------------------------------------
SQL ordered by Executions  DB/Inst: UEP/uep  Snaps: 3-4
-> End Executions Threshold:       100  Total Executions:           4,358
-> Captured SQL accounts for   63.4% of Total Executions
-> SQL reported below exceeded  1.0% of Total Executions                                                CPU per    Elap per     Old
 Executions   Rows Processed   Rows per Exec    Exec (s)   Exec (s)  Hash Value
------------ --------------- ---------------- ----------- ---------- ----------
       1,323               0              0.0       0.32        0.35 3016263992
Module: JDBC Thin Client
select pkgName from ZXAN_IPTVPKGTABLE where neId = :1 and SYS_OP
_VECBIT(userRecvPortList, LENGTH(userRecvPortList) * 4 - :2) = 1
       1,319               0              0.0       0.00        0.00 3123178563
Module: JDBC Thin Client
select pkgName, endTime, startTime from ZXAN_IPTVSCHDELETABLE wh
ere neid = :1 and portIndex = :2          -------------------------------------------------------------
SQL ordered by Parse Calls  DB/Inst: UEP/uep  Snaps: 3-4
-> End Parse Calls Threshold:      1000 Total Parse Calls:           3,111
-> Captured SQL accounts for   86.0% of Total Parse Calls
-> SQL reported below exceeded  1.0% of Total Parse Calls                           % Total    Old
 Parse Calls  Executions   Parses  Hash Value
------------ ------------ -------- ----------
       1,323        1,323    42.53 3016263992
Module: JDBC Thin Client
select pkgName from ZXAN_IPTVPKGTABLE where neId = :1 and SYS_OP
_VECBIT(userRecvPortList, LENGTH(userRecvPortList) * 4 - :2) = 1
       1,319        1,319    42.40 3123178563
Module: JDBC Thin Client
select pkgName, endTime, startTime from ZXAN_IPTVSCHDELETABLE wh
ere neid = :1 and portIndex = :2

Answer 3

我是来学习的。这种优化，itpub上高手多1.这个statspack:
Elapsed:                1.92 (mins) 时间似乎太短了，应该要15分钟左右2. Execute to Parse %:  28.61        
这个有点低3. top sql
几乎每个sql都有SYS_OP_VECBIT(userRecvPortList, LENGTH(userRecvPortList) * 4 - :2)这个东东, 看看能不能优化它？

Answer 4

可以不用做statspack.
一般cpu高消耗都是由SQL不当引起的。
先top一下，找出消耗CPU最高的进程，然后根据pid查找对应执行的sql语句。然后再对该语句进一步跟踪，并作分析。

Answer 5

既然你现在已经做了statspack，仔细看下：
SQL ordered by CPU  DB/Inst: UEP/uep  Snaps: 3-4 
-> Resources reported for PL/SQL code includes the resources used by all SQL 
  statements called by the code. 
-> Total DB CPU (s):            429 
-> Captured SQL accounts for  99.1% of Total DB CPU 
-> SQL reported below exceeded  1.0% of Total DB CPU     CPU                  CPU per            Elapsd                    Old 
  Time (s)  Executions  Exec (s)  %Total  Time (s)    Buffer Gets  Hash Value 
---------- ------------ ---------- ------ ---------- --------------- ---------- 
    423.42        1,323      0.32  98.7    462.84      3,585,450 3016263992 
Module: JDBC Thin Client 
select pkgName from ZXAN_IPTVPKGTABLE where neId = :1 and SYS_OP 
_VECBIT(userRecvPortList, LENGTH(userRecvPortList) * 4 - :2) = 1 

Answer 6

select pkgName from ZXAN_IPTVPKGTABLE where neId = :1 and SYS_OP 
_VECBIT(userRecvPortList, LENGTH(userRecvPortList) * 4 - :2) = 1 select pkgName, endTime, startTime from ZXAN_IPTVSCHDELETABLE wh 
ere neid = :1 and portIndex = :2 估计是这两个语句有问题，都执行了1000多遍，看看是不是在循环里面？

Answer 7

这东西是问不清楚的先说下你的系统环境
和SGA的分配

Answer 8

谢谢大家的回复
现在发现
select pkgName from ZXAN_IPTVPKGTABLE where neId = :1 and SYS_OP 
_VECBIT(userRecvPortList, LENGTH(userRecvPortList) * 4 - :2) = 1 以上SQL语句执行计划发生了变化，一开始是按索引扫描，后来就变为了全表扫描，所以导致了性能极具下降了。
oracle如何配置才能使得SQL的执行计划最优化呢，也就是说，如何让ORACLE执行以上SQL语句采用按索引扫描呢，谢谢大家了。

Answer 9

逻辑读确实是特别高了.sar -d的结果都啥?没有os级别的性能输出吗?从这里来看,可能大家所说的那个sql的执行计划有所变化了.select last_analyzed from dba_tables 看看这个表是否在昨天晚上被分析过或者是ppmon进行自动取样了.另外,快照时间长点,别搞得这么短.1分钟的时间不够.

Answer 10

另外,你的IO情况我们还不清楚.也有可能CPU在等wio操作也很有可能,所以建议提供更详细的信息,以便大家进行分析.

Answer 11

不过你的物理读从sp中并没有看到多高,倒是lio非常高.之前作过什么操作呢?

Answer 12

服务器始终循环执行以下两个SQL语句
select pkgName from ZXAN_IPTVPKGTABLE where neId = :1 and SYS_OP 
_VECBIT(userRecvPortList, LENGTH(userRecvPortList) * 4 - :2) = 1 select pkgName, endTime, startTime from ZXAN_IPTVSCHDELETABLE wh 
ere neid = :1 and portIndex = :2 因为没有删除，添加语句，所以ZXAN_IPTVSCHDELETABLE 表中始终保持初始20万条记录，今天察看了这两个SQL的执行计划，发现问题根源在于第一个SQL的执行计划由索引扫描变成了全表扫描，从而导致了性能急剧下降，接下来该怎么做，才能解决问题呢？

Answer 13

以下是执行计划，供大家参考
SQL> select PKGNAME from uep.ZXAN_IPTVPKGTABLE where neId = 'ManagedElementID=0,
OBJKEY=TIME1226659605505' and SYS_OP_VECBIT(userRecvPortList, LENGTH(userRecvPor
tList) * 4 - 49) = 1;no rows selectedElapsed: 00:00:00.01Execution Plan
----------------------------------------------------------
Plan hash value: 1724214933--------------------------------------------------------------------------------
--------------------| Id  | Operation                   | Name                 | Rows  | Bytes | Cos
t (%CPU)| Time     |--------------------------------------------------------------------------------
--------------------|   0 | SELECT STATEMENT            |                      |    21 | 32676 |   1
16   (0)| 00:00:02 ||*  1 |  TABLE ACCESS BY INDEX ROWID| ZXAN_IPTVPKGTABLE    |    21 | 32676 |   1
16   (0)| 00:00:02 ||*  2 |   INDEX RANGE SCAN          | PK_ZXAN_IPTVPKGTABLE |  6281 |       |
91   (0)| 00:00:02 |--------------------------------------------------------------------------------
--------------------
Predicate Information (identified by operation id):
---------------------------------------------------   1 - filter(SYS_OP_VECBIT(HEXTORAW("USERRECVPORTLIST"),LENGTH("USERRECVPORTLIS
T")*4-49)=1)   2 - access("NEID"='ManagedElementID=0,OBJKEY=TIME1226659605505')Note
-----
   - dynamic sampling used for this statement
Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
         51  consistent gets
          0  physical reads
          0  redo size
        276  bytes sent via SQL*Net to client
        373  bytes received via SQL*Net from client
          1  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          0  rows processedSQL>00000000000000' where neId = 'ManagedElementID=0,OBJKEY=TIME1226659605505' and p
kgName = 'NSP0001';1 row updated.Elapsed: 00:00:00.00Execution Plan
----------------------------------------------------------
Plan hash value: 4215894689--------------------------------------------------------------------------------
-----------| Id  | Operation          | Name                 | Rows  | Bytes | Cost (%CPU)|
 Time     |--------------------------------------------------------------------------------
-----------|   0 | UPDATE STATEMENT   |                      |     1 |  1556 |     2   (0)|
 00:00:01 ||   1 |  UPDATE            | ZXAN_IPTVPKGTABLE    |       |       |            |
          ||*  2 |   INDEX UNIQUE SCAN| PK_ZXAN_IPTVPKGTABLE |     1 |  1556 |     1   (0)|
 00:00:01 |--------------------------------------------------------------------------------
-----------
Predicate Information (identified by operation id):
---------------------------------------------------   2 - access("NEID"='ManagedElementID=0,OBJKEY=TIME1226659605505' AND
              "PKGNAME"='NSP0001')
Statistics
----------------------------------------------------------
          0  recursive calls
          1  db block gets
          3  consistent gets
          0  physical reads
        320  redo size
        677  bytes sent via SQL*Net to client
        712  bytes received via SQL*Net from client
          4  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
          1  rows processedSQL>

Answer 14

所以我问你要你看一下last_analyzed的情况是怎么样的.

Answer 15

应该是不合理 sql语句造成的。。