資料庫預設安裝配置導致的問題

yangtingkun發表於2010-12-02

協助地方公司診斷資料庫效能問題。

 

 

剛登陸資料庫伺服器,發現系統響應很慢,從作業系統的監測工具上看,系統的idle不到10,資料庫伺服器處於非常繁忙的狀態。

p570a# iostat 2 10

System configuration: lcpu=16 drives=11 paths=6 vdisks=0

tty:      tin         tout    avg-cpu: % user % sys % idle % iowait
          0.0         30.0               90.9   1.7    5.0      2.3

Disks:        % tm_act     Kbps      tps    Kb_read   Kb_wrtn
hdisk2           0.0     24208.0     1101.0      11664     36752
hdisk3           0.0       0.0       0.0          0         0
hdisk5           0.0       0.0       0.0          0         0
hdisk6           0.0       0.0       0.0          0         0
hdisk8           0.0       0.0       0.0          0         0
hdisk7           0.0       0.0       0.0          0         0
hdisk4           0.0       0.0       0.0          0         0
hdisk9           0.0       0.0       0.0          0         0
hdisk0           0.0       0.0       0.0          0         0
hdisk1           0.0       0.0       0.0          0         0
cd0              0.0       0.0       0.0          0         0
Disk history flag turned off. The current iteration disk utilization values may be inaccurate

tty:      tin         tout    avg-cpu: % user % sys % idle % iowait
          0.0        498.0               89.1   2.1    6.2      2.6

Disks:        % tm_act     Kbps      tps    Kb_read   Kb_wrtn
hdisk2           0.0     24524.0     1034.5       8836     40212
hdisk3           0.0       0.0       0.0          0         0
hdisk5           0.0       0.0       0.0          0         0
hdisk6           0.0       0.0       0.0          0         0
hdisk8           0.0       0.0       0.0          0         0
hdisk7           0.0       0.0       0.0          0         0
hdisk4           0.0       0.0       0.0          0         0
hdisk9           0.0       0.0       0.0          0         0
hdisk0           0.0      30.0       7.5          0        60
hdisk1           0.0      30.0       7.5          0        60
cd0              0.0       0.0       0.0          0         0
Disk history flag turned off. The current iteration disk utilization values may be inaccurate

.
.
.

tty:      tin         tout    avg-cpu: % user % sys % idle % iowait
          0.0        497.5               80.4   2.7   13.3      3.6

Disks:        % tm_act     Kbps      tps    Kb_read   Kb_wrtn
hdisk2           0.0     30470.0     680.5      18288     42652
hdisk3           0.0       0.0       0.0          0         0
hdisk5           0.0       0.0       0.0          0         0
hdisk6           0.0       0.0       0.0          0         0
hdisk8           0.0       0.0       0.0          0         0
hdisk7           0.0       0.0       0.0          0         0
hdisk4           0.0       0.0       0.0          0         0
hdisk9           0.0       0.0       0.0          0         0
hdisk0           0.0       0.0       0.0          0         0
hdisk1           0.0       0.0       0.0          0         0
cd0              0.0       0.0       0.0          0         0

從佔用資源較大的後臺進行找到一個sql語句,這是一個只取前10條記錄的分頁語句,在實際執行中沒有記錄返回,即使是這樣,執行也超過了50秒。而檢查對應的執行計劃並沒有發現什麼問題。簡單分析了一下,找不到問題所在,繼續檢查整個系統的情況。

SQL> SELECT SID, SERIAL#, USERNAME, EVENT, SECONDS_IN_WAIT FROM V$SESSION WHERE LOGON_TIME < SYSDATE - 5 AND USERNAME != 'SYS';

   SID    SERIAL# USERNAME             EVENT                               SECONDS_IN_WAIT
------ ---------- -------------------- ----------------------------------- ---------------
    81      41590 JIANGSREP            SQL*Net message from client                 1734662
    97       3228 JIANGSREP            SQL*Net message from client                  245416
   103      31706 JSSQ_TRADE           kksfbc child completion                     9047122
   134      11042 JIANGSREP            SQL*Net message from client                  245505
   140      40963 JIANGSREP            SQL*Net message from client                 2508546
   158      49273 JIANGSREP            SQL*Net message from client                 3540123
   237      10017 JIANGSREP            SQL*Net message from client                  850642
   246      14033 JSSQ_TRADE           SQL*Net message from client                  522290
   253      37697 JSSQ_TRADE           SQL*Net message from client                  854678
   267      22150 JIANGSREP            SQL*Net message from client                 1734675
   287      33919 JSSQ_TRADE           kksfbc child completion                     5440100
   320      49947 JSSQ_TRADE           SQL*Net message from client                    3111
   338      34648 JSSQ_TRADE           kksfbc child completion                     6477167
   414      31881 JSSQ_TRADE           SQL*Net message from client                      87
   447      21579 JSSQ_TRADE           SQL*Net message from client                     220
   479      34580 JSSQ_TRADE           kksfbc child completion                     8647549

16 rows selected.

系統中存在很多登陸時間超過5條的會話,這對於當前系統而言,可能性不大,且觀察SECONDS_IN_WAIT列的等待時間,顯然這些會話的狀態並不正常。雖然SQL*Net message from client是空閒狀態,但是如果出現了網路閃斷,會話也可能處於這種狀態,且會一直佔用大量的CPU資源,而當前就是這種症狀。

在作業系統中找到這些長時間等待的程式,確認這些程式不屬於Oracle的後臺進行,將這些程式用kill -9命令結束掉:

SQL> SELECT SPID FROM V$PROCESS
  2  WHERE ADDR IN (SELECT PADDR FROM V$SESSION WHERE SID IN (81, 97, 103, 134, 140, 158, 237, 246, 253, 267, 287, 320, 338, 479));

SPID
------------
1597770
1786238
1306960
786582
1015972
376952
1212566
356998
770692
1421972
693036
762560
1377278
1609872

14 rows selected.

$ ps -ef|grep 1597770
  oracle 1355892  672288   0 11:05:43  pts/5  0:00 grep 1597770
  oracle 1597770       1   0   Jul 30      -  0:03 oracletrade (LOCAL=NO)
$ kill -9 1597770
$ ps -ef|grep 1786238
  oracle 1630318  672288   0 11:06:31  pts/5  0:00 grep 1786238
  oracle 1786238       1   0   Jul 30      -  0:08 oracletrade (LOCAL=NO)
$ kill -9 1786238
$ ps -ef |grep 1306960
  oracle  504028  672288   0 11:08:08  pts/5  0:00 grep 1306960
  oracle 1306960       1  85   May 27      - 148536:45 oracletrade (LOCAL=NO)
$ kill -9 1306960
.
.
.
$ ps -ef|grep 762560
  oracle 1307044  672288   0 11:15:20  pts/5  0:00 grep 762560
  oracle  762560       1   0   Sep 02      -  3:40 oracletrade (LOCAL=NO)
$ kill -9 762560

清除掉處於長時間等待的這些程式,再次檢查系統狀態:

$ iostat 2 10

System configuration: lcpu=16 drives=11 paths=6 vdisks=0

tty:      tin         tout    avg-cpu: % user % sys % idle % iowait
          0.0         30.0               57.3   1.6   23.6     17.5

Disks:        % tm_act     Kbps      tps    Kb_read   Kb_wrtn
hdisk2           0.0     12638.0     651.0       3372     21904
hdisk3           0.0       0.0       0.0          0         0
hdisk5           0.0       0.0       0.0          0         0
hdisk6           0.0       0.0       0.0          0         0
hdisk8           0.0       0.0       0.0          0         0
hdisk7           0.0       0.0       0.0          0         0
hdisk4           0.0       0.0       0.0          0         0
hdisk9           0.0       0.0       0.0          0         0
hdisk0           0.0       0.0       0.0          0         0
hdisk1           0.0       0.0       0.0          0         0
cd0              0.0       0.0       0.0          0         0
Disk history flag turned off. The current iteration disk utilization values may be inaccurate

tty:      tin         tout    avg-cpu: % user % sys % idle % iowait
          0.0        497.7               59.0   2.3   19.3     19.5

Disks:        % tm_act     Kbps      tps    Kb_read   Kb_wrtn
hdisk2           0.0     19218.0     953.8       5736     32688
hdisk3           0.0       0.0       0.0          0         0
hdisk5           0.0       0.0       0.0          0         0
hdisk6           0.0       0.0       0.0          0         0
hdisk8           0.0       0.0       0.0          0         0
hdisk7           0.0       0.0       0.0          0         0
hdisk4           0.0       0.0       0.0          0         0
hdisk9           0.0       0.0       0.0          0         0
hdisk0           0.0       0.0       0.0          0         0
hdisk1           0.0       0.0       0.0          0         0
cd0              0.0       0.0       0.0          0         0
Disk history flag turned off. The current iteration disk utilization values may be inaccurate

tty:      tin         tout    avg-cpu: % user % sys % idle % iowait
          0.0        497.5               59.3   2.2   23.5     15.0

Disks:        % tm_act     Kbps      tps    Kb_read   Kb_wrtn
hdisk2           0.0     19272.0     536.0        580     37964
hdisk3           0.0       0.0       0.0          0         0
hdisk5           0.0       0.0       0.0          0         0
hdisk6           0.0       0.0       0.0          0         0
hdisk8           0.0       0.0       0.0          0         0
hdisk7           0.0       0.0       0.0          0         0
hdisk4           0.0       0.0       0.0          0         0
hdisk9           0.0       0.0       0.0          0         0
hdisk0           0.0       0.0       0.0          0         0
hdisk1           0.0       0.0       0.0          0         0
cd0              0.0       0.0       0.0          0         0
Disk history flag turned off. The current iteration disk utilization values may be inaccurate

.
.
.

tty:      tin         tout    avg-cpu: % user % sys % idle % iowait
          0.0        497.5               61.1   2.5   20.6     15.9

Disks:        % tm_act     Kbps      tps    Kb_read   Kb_wrtn
hdisk2           0.0     21254.0     820.5        804     41704
hdisk3           0.0       0.0       0.0          0         0
hdisk5           0.0       0.0       0.0          0         0
hdisk6           0.0       0.0       0.0          0         0
hdisk8           0.0       0.0       0.0          0         0
hdisk7           0.0       0.0       0.0          0         0
hdisk4           0.0       0.0       0.0          0         0
hdisk9           0.0       0.0       0.0          0         0
hdisk0           0.0       0.0       0.0          0         0
hdisk1           0.0       0.0       0.0          0         0
cd0              0.0       0.0       0.0          0         0
Disk history flag turned off. The current iteration disk utilization values may be inaccurate

顯然,殺掉了長時間執行的會話後,系統的idle從原來的不到10%,上升到20%以上,說明系統的壓力有了緩解,等待一段時間後,idle的值進一步上升。

這時在檢查剛才執行超過50秒的SQL,這次發現SQL執行時間不到0.1秒,看來剛才的SQL本身沒有什麼問題,只不過剛才整個系統都處於極度繁忙的狀態,SQL執行所需要的資源、LATCH、鎖等都被佔用,因此出現了長時間的等待。這從片面也說明一個問題,系統的網路肯定是發生過閃斷,導致了大量的會話處於等待的狀態,消耗的大量的系統資源,直至系統資源被耗盡。

解決這個問題後,系統的壓力開始慢慢降低,但是觀察發現,雖然現在資料庫中的會話並不多,但是資料庫並沒有處於比較空閒的狀態。這說明系統還存在其他的問題。

檢查資料庫的alert檔案時,發現一個問題。

首先,日誌切換過於頻繁:

$ tail -200 alert_trade.log
Thu Sep  9 08:10:41 2010
Thread 1 advanced to log sequence 4566 (LGWR switch)
  Current log# 2 seq# 4566 mem# 0: /oracle01/app/oracle/oradata/trade/trade/redo02.log
Thu Sep  9 08:15:47 2010
Thread 1 advanced to log sequence 4567 (LGWR switch)
  Current log# 3 seq# 4567 mem# 0: /oracle01/app/oracle/oradata/trade/trade/redo03.log
Thu Sep  9 08:20:57 2010
Thread 1 advanced to log sequence 4568 (LGWR switch)
  Current log# 1 seq# 4568 mem# 0: /oracle01/app/oracle/oradata/trade/trade/redo01.log
Thu Sep  9 08:24:39 2010
Thread 1 advanced to log sequence 4569 (LGWR switch)
  Current log# 2 seq# 4569 mem# 0: /oracle01/app/oracle/oradata/trade/trade/redo02.log
Thu Sep  9 08:28:28 2010
Thread 1 advanced to log sequence 4570 (LGWR switch)
  Current log# 3 seq# 4570 mem# 0: /oracle01/app/oracle/oradata/trade/trade/redo03.log
Thu Sep  9 08:33:15 2010
Thread 1 advanced to log sequence 4571 (LGWR switch)
  Current log# 1 seq# 4571 mem# 0: /oracle01/app/oracle/oradata/trade/trade/redo01.log
Thu Sep  9 08:37:12 2010
Thread 1 advanced to log sequence 4572 (LGWR switch)
  Current log# 2 seq# 4572 mem# 0: /oracle01/app/oracle/oradata/trade/trade/redo02.log
Thu Sep  9 08:41:19 2010
Thread 1 advanced to log sequence 4573 (LGWR switch)
  Current log# 3 seq# 4573 mem# 0: /oracle01/app/oracle/oradata/trade/trade/redo03.log
Thu Sep  9 08:45:17 2010
Thread 1 advanced to log sequence 4574 (LGWR switch)
  Current log# 1 seq# 4574 mem# 0: /oracle01/app/oracle/oradata/trade/trade/redo01.log
Thu Sep  9 08:48:44 2010
Thread 1 advanced to log sequence 4575 (LGWR switch)
  Current log# 2 seq# 4575 mem# 0: /oracle01/app/oracle/oradata/trade/trade/redo02.log
Thu Sep  9 08:51:45 2010
Thread 1 advanced to log sequence 4576 (LGWR switch)
  Current log# 3 seq# 4576 mem# 0: /oracle01/app/oracle/oradata/trade/trade/redo03.log
Thu Sep  9 08:55:19 2010
Thread 1 advanced to log sequence 4577 (LGWR switch)
  Current log# 1 seq# 4577 mem# 0: /oracle01/app/oracle/oradata/trade/trade/redo01.log
Thu Sep  9 08:58:15 2010
Thread 1 advanced to log sequence 4578 (LGWR switch)
  Current log# 2 seq# 4578 mem# 0: /oracle01/app/oracle/oradata/trade/trade/redo02.log
Thu Sep  9 09:00:50 2010
Thread 1 advanced to log sequence 4579 (LGWR switch)
  Current log# 3 seq# 4579 mem# 0: /oracle01/app/oracle/oradata/trade/trade/redo03.log
Thu Sep  9 09:03:40 2010
Thread 1 advanced to log sequence 4580 (LGWR switch)
  Current log# 1 seq# 4580 mem# 0: /oracle01/app/oracle/oradata/trade/trade/redo01.log
Thu Sep  9 09:06:43 2010
Thread 1 advanced to log sequence 4581 (LGWR switch)
.
.
.
Thu Sep  9 10:00:04 2010
Thread 1 advanced to log sequence 4593 (LGWR switch)
  Current log# 2 seq# 4593 mem# 0: /oracle01/app/oracle/oradata/trade/trade/redo02.log
Thu Sep  9 10:08:42 2010
Thread 1 advanced to log sequence 4594 (LGWR switch)
  Current log# 3 seq# 4594 mem# 0: /oracle01/app/oracle/oradata/trade/trade/redo03.log
Thu Sep  9 10:18:18 2010
Thread 1 advanced to log sequence 4595 (LGWR switch)

可以看到,在系統忙時,每23分鐘就需要切換一次redo檔案,檢查資料庫中redo的配置:

SQL> SELECT * FROM V$LOG;

    GROUP#    THREAD#  SEQUENCE#    BYTES  MEMBERS ARC STATUS    FIRST_CHANGE# FIRST_TIME
---------- ---------- ---------- -------- -------- --- --------- ------------- ----------
         1          1       4616 52428800        1 NO  CURRENT       609502223 09-SEP-10
         2          1       4614 52428800        1 YES INACTIVE      609466117 09-SEP-10
         3          1       4615 52428800        1 YES INACTIVE      609475846 09-SEP-10

每個日誌檔案才分配了50M,難怪系統頻繁的切換日誌。懷疑安裝資料庫的時候採用了預設的配置。

既然日誌檔案大小預設配置,不會系統中的記憶體引數也是預設配置大小吧,檢查資料庫中SGA配置:

SQL> show sga

Total System Global Area 8589934592 bytes
Fixed Size                  2097760 bytes
Variable Size            5268049312 bytes
Database Buffers         3305111552 bytes
Redo Buffers               14675968 bytes
SQL> show parameter pga

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
pga_aggregate_target                 big integer 1G

SGA分配8GPGA分配1G,作業系統有32G記憶體,這個分配顯然不合理。

進一步檢查系統的記憶體分配情況:

SQL> show parameter cache

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_16k_cache_size                    big integer 0
db_2k_cache_size                     big integer 0
db_32k_cache_size                    big integer 0
db_4k_cache_size                     big integer 0
db_8k_cache_size                     big integer 0
db_cache_advice                      string      ON
db_cache_size                        big integer 3104M
db_keep_cache_size                   big integer 0
db_recycle_cache_size                big integer 0
object_cache_max_size_percent        integer     10
object_cache_optimal_size            integer     102400
session_cached_cursors               integer     20

SQL> show parameter sga_target

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
sga_target                           big integer 6560M

使用者僅指定了6G的記憶體給SGAOracle在自動分配的時候還將大部分給了共享池,只給了DB_CACHE不到3G的空間,難怪系統效能很差。

調整了SGA以及redo檔案的大小,並重啟資料庫後,效能問題解決。

 

 

來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/4227/viewspace-680841/,如需轉載,請註明出處,否則將追究法律責任。

相關文章