75 积分	1 好友	8 主题

发消息

客户端无法连接数据库

1^#

发表于 2012-5-17 12:31:50 | 查看: 7619| 回复: 7

最近客户反映，有段时间内无法连接到数据库做业务。
查看数据库在时间段内的状态和日志，也没有发现导致无法连接的原因。以下是相关的以下日志文件和时间段内的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（单实例文件系统）

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

awrrpt_1_2366_2397.html

524.48 KB, 下载次数: 802

分享0

收藏0 回复只看该作者道具举报

Maclean Liu(刘相兵

2^#

发表于 2012-5-17 13:01:11

已上传的AWR 时间跨度过久

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

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

回复只看该作者道具举报

yehc@epsoft.com

3^#

发表于 2012-5-17 13:15:25

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

addmrpt_1_2394_2396.txt

12.96 KB, 下载次数: 835

awrrpt_1_2394_2396.html

490.19 KB, 下载次数: 754

回复只看该作者道具举报

Maclean Liu(刘相兵

4^#

发表于 2012-5-17 13:23:41

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

5^#

发表于 2012-6-11 23:10:42

刘大你好，上个月提过关于客户端无法连接数据库的问题。
这个问题今天下午又出现了，之前您也怀疑系统本身是否有其他应用程序占用大量的内存。
现在的情况是：
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状态。而该瓶颈直接导致了客户端请求数据库的挂起。

awrrpt_1_3023_3025.html

464.81 KB, 下载次数: 756

addmrpt_1_3023_3025.txt

6.65 KB, 下载次数: 805

回复只看该作者道具举报

miloluo

6^#

发表于 2012-6-12 09:55:17

从AWR的等待事件来看：

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

复制代码

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

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

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

复制代码

回复只看该作者道具举报

不了峰

7^#

发表于 2012-6-12 10:59:49

是不是 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

回复只看该作者道具举报

Maclean Liu(刘相兵

8^#

发表于 2012-6-12 11:20:36

就日志和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参数

回复只看该作者道具举报

返回列表

		自动登录	找回密码
密码			注册