客户端无法连接数据库

yehc@epsoft.com

最近客户反映，有段时间内无法连接到数据库做业务。
查看数据库在时间段内的状态和日志，也没有发现导致无法连接的原因。以下是相关的以下日志文件和时间段内的AWR报告。麻烦大家帮分析看看

1 alert log：
Thread 1 advanced to log sequence 850 (LGWR switch)
  Current log# 1 seq# 850 mem# 0: /oradata/wzsb/redo01.log
  Current log# 1 seq# 850 mem# 1: /oradata/wzsb/redo04.log
Wed May 16 10:52:49 2012


***********************************************************************

Fatal NI connect error 12170.

  VERSION INFORMATION:
    TNS for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
    TCP/IP NT Protocol Adapter for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
    Oracle Bequeath NT Protocol Adapter for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
  Time: 16-MAY-2012 10:52:49
  Tracing not turned on.
  Tns error struct:
    ns main err code: 12535
   
TNS-12535: TNS:operation timed out
    ns secondary err code: 12560
    nt main err code: 505
   
TNS-00505: Operation timed out
    nt secondary err code: 78
    nt OS err code: 0
  Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.100.30)(PORT=2145))
Wed May 16 11:11:10 2012
WARNING: Heavy swapping observed on system in last 5 mins.
pct of memory swapped in [3.52%] pct of memory swapped out [0.04%].
Please make sure there is no memory pressure and the SGA and PGA
are configured correctly. Look at DBRM trace file for more details.
Wed May 16 11:25:38 2012
这里好像是有内存溢出的现象。接下来看了相应的DBRM trace文件的确有内存溢出：
*** 2012-05-16 11:11:10.869
total swpin [ 3.52%][1141144K], total swpout [ 0.04%][16136K]
vm stats captured every 30 secs for last 5 mins:
swpin:                 swpout:  
[ 0.00%][       652K]  [ 0.00%][      2748K]
[ 0.14%][     45572K]  [ 0.00%][      1384K]
[ 0.29%][     95644K]  [ 0.00%][      1588K]
[ 0.30%][     99784K]  [ 0.00%][      1636K]
[ 0.25%][     83356K]  [ 0.00%][      1504K]
[ 0.26%][     85156K]  [ 0.00%][      1688K]
[ 0.17%][     56104K]  [ 0.00%][      1112K]
[ 0.67%][    219396K]  [ 0.00%][      1708K]
[ 1.10%][    357972K]  [ 0.00%][      1316K]
[ 0.30%][     97508K]  [ 0.00%][      1452K]
Heavy swapping observed in last 5 mins:    [pct of total memory][bytes]
接下来收集了当天6:00到13：00的AWR报告。
总体感觉跟网络堵塞的关系比较大，不知道分析的对不对

为什么会内存溢出，现在还没找到原因？？

但是从13点以后业务又正常了。

环境：AIX+HACMP+11.2.0.3（单实例文件系统）

还请刘大帮忙分析看看。。。

Maclean Liu(刘相兵

就日志和ADDM来看 存在严重的swap

WARNING: Heavy swapping observed on system in last 5 mins.
pct of memory swapped in [2.21%] pct of memory swapped out [0.03%].

Significant virtual memory paging was detected on the host operating system.

   Recommendation 1: Host Configuration
   Estimated benefit is .3 active sessions, 100% of total activity.
   ----------------------------------------------------------------
   Action
      Host operating system was experiencing significant paging but no
      particular root cause could be detected. Investigate processes that do
      not belong to this instance running on the host that are consuming
      significant amount of virtual memory. Also consider adding more physical
      memory to the host.


物理内存 30.88GB  % Host Mem used for SGA+PGA:         30.80         30.78


建议你检查系统中是否存在其他 消耗内存引发swap的程序，并调优AIX VMO参数

不了峰

是不是 AIX 内存 设置在做怪

好象默认是 最大预分配文件系统占用内存是80% --这个描述不知道准不准确

  – minperm%=5 (default 20)
   ? Target for minimum % of physical memory to be used for file system cache
   
   – maxperm%=15 ( default 80)  
   检查方法:
   # vmstat -v
   ....
   20.0 minperm percentage                 
   80.0 maxperm percentage

miloluo

从AWR的等待事件来看：

1. Top 5 Timed Foreground Events
   
2. 
   
3. Event        Waits        Time(s)        Avg wait (ms)        % DB time        Wait Class
   
4. enq: TX - row lock contention        25        1,922        76876        89.85        Application
   
5. DB CPU                 137                 6.42         
   
6. db file sequential read        12,458        54        4        2.54        User I/O
   
7. log file sync        2,649        10        4        0.45        Commit
   
8. SQL*Net more data from client        607        6        10        0.27        Network

复制代码

"enq: TX - row lock contention"是主要问题。

ADDM中能看到对于这个等待事件作出的分析：

1. Finding 2: Row Lock Waits
   
2. Impact is .27 active sessions, 89.85% of total activity.
   
3. --------------------------------------------------------
   
4. SQL statements were found waiting for row lock waits.
   
5. 
   
6.    Recommendation 1: Application Analysis
   
7.    Estimated benefit is .27 active sessions, 89.85% of total activity.
   
8.    -------------------------------------------------------------------
   
9.    Action
   
10.       Significant row contention was detected in the TABLE
    
11.       "WZSB.SYNC_BTBL_GLO_DATA" with object ID 77997. Trace the cause of row
    
12.       contention in the application logic using the given blocked SQL.
    
13.       Related Object
    
14.          Database object with ID 77997.
    
15.    Rationale
    
16.       The SQL statement with SQL_ID "70c5u0b6t1tdy" was blocked on row locks.
    
17.       Related Object
    
18.          SQL statement with SQL_ID 70c5u0b6t1tdy.
    
19.          UPDATE WZSB.SYNC_BTBL_GLO_DATA SET BEE_ISUPDATE = '1',BEE_ISSYNC =
    
20.          '0',BEE_UPDATETIME = :B1 WHERE TABLE_NAME = 'SBDS_LOG'
    
21.    Rationale
    
22.       The session with ID 255 and serial number 49615 in instance number 1 was
    
23.       the blocking session responsible for 100% of this recommendation's
    
24.       benefit.

复制代码

yehc@epsoft.com

刘大你好，上个月提过关于客户端无法连接数据库的问题。
这个问题今天下午又出现了，之前您也怀疑系统本身是否有其他应用程序占用大量的内存。
现在的情况是：
1、两台IBM 720机器+HACMP+Oracle11.2.0.3（单实例）；
2、操作系统版本：
# oslevel -s
6100-06-04-1112
3、共享VG对应的磁盘属性：
# lsattr -El updisk0
PCM             PCM/friend/UPpcm_S5500T          Path Control Module              False
PR_key_value    none                             Persistant Reserve Key Value     True
algorithm       fail_over                        Algorithm                        True
clr_q           no                               Device CLEARS its Queue on error True
device_mode     0                                Reserve Policy                   True
dist_err_pcnt   0                                Distributed Error Percentage     True
dist_tw_width   50                               Distributed Error Sample Time    True
dvc_support                                      Device Support                   False
hcheck_cmd      test_unit_rdy                    Health Check Command             True
hcheck_interval 30                               Health Check Interval            True
hcheck_mode     nonactive                        Health Check Mode                True
location                                         Location Label                   True
lun_id          0x0                              Logical Unit Number ID           False
lun_reset_spt   yes                              LUN Level Reset                  True
max_transfer    0x40000                          Maximum TRANSFER Size            True
node_name       0x21000022a10a09a2               FC Node Name                     False
pvid            00f7132cc8509d1d0000000000000000 Physical volume identifier       False
q_err           yes                              Use QERR bit                     True
q_type          simple                           Queuing TYPE                     True
queue_depth     5                                Queue DEPTH                      True
reassign_to     120                              REASSIGN time out value          True
reserve_policy  no_reserve                       Reserve Policy                   True
rw_timeout      30                               READ/WRITE time out value        True
scsi_id         0x100e0                          SCSI ID                          False
start_timeout   60                               START unit time out value        True
ww_name         0x20080022a10a09a2               FC World Wide Name     

4、下午15点到17点之间再次出现客户端无法连接数据库的问题；并收集了相应的AWR报告和ADDM快照。（附件中）

5、查看数据库日志（凌晨到下午2点，之后没有新的日志，业务量不大的生产库），发现：
Mon Jun 11 00:00:00 2012
Setting Resource Manager plan SCHEDULER[0x318F]:DEFAULT_MAINTENANCE_PLAN via scheduler
window
Setting Resource Manager plan DEFAULT_MAINTENANCE_PLAN via parameter
Mon Jun 11 00:00:00 2012
Begin automatic SQL Tuning Advisor run for special tuning task  "SYS_AUTO_SQL_TUNING_T
ASK"
Mon Jun 11 00:00:58 2012
Thread 1 cannot allocate new log, sequence 932
Private strand flush not complete
  Current log# 1 seq# 931 mem# 0: /oradata/wzsb/redo01.log
  Current log# 1 seq# 931 mem# 1: /oradata/wzsb/redo04.log
Thread 1 advanced to log sequence 932 (LGWR switch)
  Current log# 2 seq# 932 mem# 0: /oradata/wzsb/redo02.log
  Current log# 2 seq# 932 mem# 1: /oradata/wzsb/redo05.log
Mon Jun 11 00:04:37 2012
Thread 1 advanced to log sequence 933 (LGWR switch)
  Current log# 3 seq# 933 mem# 0: /oradata/wzsb/redo03.log
  Current log# 3 seq# 933 mem# 1: /oradata/wzsb/redo06.log
Mon Jun 11 00:21:18 2012
End automatic SQL Tuning Advisor run for special tuning task  "SYS_AUTO_SQL_TUNING_TAS
K"
Mon Jun 11 02:00:00 2012
Closing scheduler window
Closing Resource Manager plan via scheduler window
Clearing Resource Manager plan via parameter
Mon Jun 11 11:21:24 2012
WARNING: Heavy swapping observed on system in last 5 mins.
pct of memory swapped in [2.21%] pct of memory swapped out [0.03%].
Please make sure there is no memory pressure and the SGA and PGA
are configured correctly. Look at DBRM trace file for more details.
Mon Jun 11 12:26:25 2012
WARNING: Heavy swapping observed on system in last 5 mins.
pct of memory swapped in [4.37%] pct of memory swapped out [0.02%].
Please make sure there is no memory pressure and the SGA and PGA
are configured correctly. Look at DBRM trace file for more details.
Mon Jun 11 14:44:22 2012
Thread 1 advanced to log sequence 934 (LGWR switch)
  Current log# 1 seq# 934 mem# 0: /oradata/wzsb/redo01.log
  Current log# 1 seq# 934 mem# 1: /oradata/wzsb/redo04.log


DBRM trace文件：
*** 2012-06-11 12:26:25.015
Heavy swapping observed in last 5 mins:    [pct of total memory][bytes]
total swpin [ 4.37%][1415248K], total swpout [ 0.02%][8320K]
vm stats captured every 30 secs for last 5 mins:
swpin:                 swpout:  
[ 0.48%][    158056K]  [ 0.00%][      1032K]
[ 0.75%][    244992K]  [ 0.00%][      1264K]
[ 0.65%][    211352K]  [ 0.00%][       768K]
[ 0.57%][    186300K]  [ 0.00%][       600K]
[ 0.52%][    168356K]  [ 0.00%][       816K]
[ 0.22%][     73656K]  [ 0.00%][       616K]
[ 0.25%][     81904K]  [ 0.00%][       872K]
[ 0.30%][     98412K]  [ 0.00%][       640K]
[ 0.29%][     96360K]  [ 0.00%][       792K]
[ 0.29%][     95860K]  [ 0.00%][       920K]

5、查看系统存在大量的aioserver进程：
# pstat -a |grep -c aios
96
# ps -k |grep aioserver
  4194514      -  0:00 aioserver
  8650940      -  0:00 aioserver
11272276      -  0:00 aioserver
11468964      -  0:00 aioserver
11599972      -  0:00 aioserver
11796566      -  0:01 aioserver
11927700      -  0:00 aioserver
13172926      -  0:00 aioserver
13303842      -  0:01 aioserver
13762712      -  0:00 aioserver
14090354      -  0:00 aioserver
15532114      -  0:00 aioserver
16449742      -  0:00 aioserver
17956934      -  0:00 aioserver
20774968      -  0:00 aioserver
21233676      -  0:00 aioserver
21299274      -  0:00 aioserver
22020200      -  0:00 aioserver
22216742      -  0:00 aioserver
23199968      -  0:00 aioserver
23330964      -  0:00 aioserver
23724160      -  0:00 aioserver
23855282      -  0:00 aioserver
24379610      -  0:00 aioserver
24445060      -  0:00 aioserver
24576014      -  0:00 aioserver
24903820      -  0:00 aioserver
26017976      -  0:00 aioserver
26607628      -  0:00 aioserver
26738856      -  0:00 aioserver
27263160      -  0:00 aioserver
27459762      -  0:00 aioserver
27852978      -  0:00 aioserver
28115022      -  0:00 aioserver
30081246      -  0:00 aioserver
30212244      -  0:00 aioserver
30474308      -  0:00 aioserver
30801996      -  0:00 aioserver
34144490      -  0:00 aioserver
34275528      -  0:00 aioserver
35127418      -  0:00 aioserver
35520514      -  0:00 aioserver
36110446      -  0:00 aioserver
36241504      -  0:00 aioserver
36503638      -  0:00 aioserver
37552242      -  0:00 aioserver
38404290      -  0:00 aioserver
39321840      -  0:00 aioserver
39452772      -  0:00 aioserver
39649412      -  0:00 aioserver
39977070      -  0:00 aioserver
42074252      -  0:00 aioserver
42795016      -  0:00 aioserver
43712760      -  0:00 aioserver
46661642      -  0:00 aioserver
47448190      -  0:00 aioserver
52166860      -  0:00 aioserver
52559932      -  0:00 aioserver
54329510      -  0:00 aioserver
54395070      -  0:00 aioserver
55443516      -  0:00 aioserver
55967774      -  0:00 aioserver
58327122      -  0:00 aioserver
59769068      -  0:00 aioserver
59834474      -  0:00 aioserver
60358894      -  0:00 aioserver
62455996      -  0:00 aioserver
62521394      -  0:00 aioserver
62718074      -  0:00 aioserver
63635558      -  0:00 aioserver
64028864      -  0:00 aioserver
64946376      -  0:00 aioserver
65405100      -  0:00 aioserver
66322562      -  0:00 aioserver
66781332      -  0:00 aioserver
   131550      -  0:00 aioserver
   524624      -  0:00 aioserver
  2032088      -  0:00 aioserver
  2687256      -  0:00 aioserver
  3932538      -  0:01 aioserver
  4063498      -  0:00 aioserver
  5505458      -  0:00 aioserver
  6554032      -  0:00 aioserver
  6947254      -  0:00 aioserver
  7012846      -  0:00 aioserver
  7078226      -  0:00 aioserver
  7143688      -  0:00 aioserver
  7209424      -  0:00 aioserver
  8847708      -  0:00 aioserver
  9372134      -  0:00 aioserver
  9437574      -  0:00 aioserver
10027344      -  0:00 aioserver
10486068      -  0:00 aioserver
11403530      -  0:00 aioserver
11862486      -  0:00 aioserver
12059118      -  0:00 aioserver

问题：
该存储是否存在IO性能上的瓶颈。导致数据库对存储IO请求的时候，存储处于wait状态。而该瓶颈直接导致了客户端请求数据库的挂起。

Maclean Liu(刘相兵

ODM DATA:

Significant virtual memory paging was detected on the host operating system.

   Recommendation 1: Host Configuration
   Estimated benefit is 1.05 active sessions, 100% of total activity.
   ------------------------------------------------------------------
   Action
      Host operating system was experiencing significant paging but no
      particular root cause could be detected. Investigate processes that do
      not belong to this instance running on the host that are consuming
      significant amount of virtual memory. Also consider adding more physical
      memory to the host.


确实存在大量的SWAP  ， 但是不是ORACLE INSTANCE PGA 或SGA引起的 ， 建议检查 其他进程是否使用了大量内存。

在快照期间 SGA+PGA 的总内存使用量 占 物理内存的 30%左右

Begin        End
Host Mem (MB):        31,616.0        31,616.0
SGA use (MB):        9,504.0        9,504.0
PGA use (MB):        271.5        239.0
% Host Mem used for SGA+PGA:        30.92        30.82



期间出现过 少量 os thread startup 的等待 ，该等待事件意味着 session login 时无法很快分配os process进程，可能导致登录挂起。

Background Wait Events

    ordered by wait time desc, waits desc (idle events last)
    Only events with Total Wait Time (s) >= .001 are shown
    %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0

Event        Waits        %Time -outs        Total Wait Time (s)        Avg wait (ms)        Waits /txn        % bg time
os thread startup        280        0        36        128        0.15        34.37




若存有 OS 性能历史信息 可以查询 在 该时段 是否有 其他应用程序消耗了大量内存 ， 也建议你 部署 OS watcher 之类的工具收集。

yehc@epsoft.com

报告已上传
请刘大再帮忙看看！！！

Maclean Liu(刘相兵

已上传的AWR 时间跨度 过久


上传 May 16 10:00- 12:00 的AWR 和 ADDM 快照

@?/rdbms/admin/awrrpt
@?/rdbms/admin/addmrpt