10G 数据库性能急剧下降

bayannur

Oracle Database 10g Enterprise Edition Release 10.2.0.5.0 - 64bi
单机 redhat release 5.4 (Final) 64G内存
8月19号早上8点左右，数据库非常卡，linux主机 load最高时曾达到1500。这个数据库每隔一段时间就会出现性能急剧下降的情况，奇怪的是出现这种现象的时间都是
非业务高峰期，根据业务介绍早上8点的时候应该没有多少量。
awrrpt_1_5032_5033.html为今天性能急剧下降的awr
awrrpt_1_5008_5009.html为前一天统计的awr
同志们帮忙看看吧，多谢啦

Maclean Liu(刘相兵

Event        Waits        Time(s)        Avg Wait(ms)        % Total Call Time        Wait Class
latch: cache buffers chains        1,670,081        2,107,649        1,262        68.8        Concurrency

Buffer Gets        Executions        Gets per Exec        %Total        CPU Time (s)        Elapsed Time (s)        SQL Id        SQL Module        SQL Text
133,671,121        393,955        339.31        68.66        5394.56        2232532.35        9hfkh0vxd9wq0        YB_UnicomCzA93.exe        SELECT HF_SERIALID FROM (SELEC...

Maclean Liu(刘相兵

1. key point 9hfkh0vxd9wq0        
   
2. 
   
3. 
   
4. select plan_table_output from table (dbms_xplan.display_awr('9hfkh0vxd9wq0',null,null,'ADVANCED+PEEKED_BINDS'));
   
5. 
   
6. 
   
7.    SELECT *
   
8.     FROM (SELECT '1.v$sql'||'实例号:'||GV$SQL.inst_id source,
   
9.                  SQL_ID,
   
10.                  plan_hash_value,
    
11.                  TO_CHAR (FIRST_LOAD_TIME) begin_time,
    
12.                  '在cursor cache中' end_time,
    
13.                  executions "No. of exec",
    
14.                  (buffer_gets / executions) "LIO/exec",
    
15.                  (cpu_time / executions / 1000000) "CPUTIM/exec",
    
16.                  (elapsed_time / executions / 1000000) "ETIME/exec",
    
17.                  (disk_reads / executions) "PIO/exec",
    
18.                  (ROWS_PROCESSED / executions) "ROWs/exec"
    
19.             FROM Gv$SQL
    
20.            WHERE sql_id = '9hfkh0vxd9wq0'
    
21.           UNION ALL
    
22.           SELECT '2.sqltuning set' source,
    
23.                  sql_id,
    
24.                  plan_hash_value,
    
25.                  'JUST SQLSET NO DATE' begin_time,
    
26.                  'JUST SQLSET NO DATE' end_time,
    
27.                  EXECUTIONS "No. of exec",
    
28.                  (buffer_gets / executions) "LIO/exec",
    
29.                  (cpu_time / executions / 1000000) "CPUTIM/exec",
    
30.                  (elapsed_time / executions / 1000000) "ETIME/exec",
    
31.                  (disk_reads / executions) "PIO/exec",
    
32.                  (ROWS_PROCESSED / executions) "ROWs/exec"
    
33.             FROM dba_sqlset_statements
    
34.            WHERE SQL_ID = '9hfkh0vxd9wq0'
    
35.           UNION ALL
    
36.           SELECT '3.dba_advisor_sqlstats' source,
    
37.                  sql_id,
    
38.                  plan_hash_value,
    
39.                  'JUST SQLSET NO DATE' begin_time,
    
40.                  'JUST SQLSET NO DATE' end_time,
    
41.                  EXECUTIONS "No. of exec",
    
42.                  (buffer_gets / executions) "LIO/exec",
    
43.                  (cpu_time / executions / 1000000) "CPUTIM/exec",
    
44.                  (elapsed_time / executions / 1000000) "ETIME/exec",
    
45.                  (disk_reads / executions) "PIO/exec",
    
46.                  (ROWS_PROCESSED / executions) "ROWs/exec"
    
47.             FROM dba_sqlset_statements
    
48.            WHERE SQL_ID = '9hfkh0vxd9wq0'
    
49.           UNION ALL
    
50.           SELECT DISTINCT
    
51.                  '4.dba_hist_sqlstat' || '实例号:' || SQL.INSTANCE_NUMBER
    
52.                     source,
    
53.                  sql_id,
    
54.                  PLAN_HASH_VALUE,
    
55.                  TO_CHAR (s.BEGIN_INTERVAL_TIME ,'YYYY-MM-DD hh24:mi:ss') begin_time,
    
56.                  TO_CHAR (s.END_INTERVAL_TIME,'YYYY-MM-DD hh24:mi:ss') end_time,
    
57.                  SQL.executions_delta,
    
58.                  SQL.buffer_gets_delta
    
59.                  / DECODE (NVL (SQL.executions_delta, 0),
    
60.                            0, 1,
    
61.                            SQL.executions_delta)
    
62.                     "LIO/exec",
    
63.                  (SQL.cpu_time_delta / 1000000)
    
64.                  / DECODE (NVL (SQL.executions_delta, 0),
    
65.                            0, 1,
    
66.                            SQL.executions_delta)
    
67.                     "CPUTIM/exec",
    
68.                  (SQL.elapsed_time_delta / 1000000)
    
69.                  / DECODE (NVL (SQL.executions_delta, 0),
    
70.                            0, 1,
    
71.                            SQL.executions_delta)
    
72.                     "ETIME/exec",
    
73.                  SQL.DISK_READS_DELTA
    
74.                  / DECODE (NVL (SQL.executions_delta, 0),
    
75.                            0, 1,
    
76.                            SQL.executions_delta)
    
77.                     "PIO/exec",
    
78.                  SQL.ROWS_PROCESSED_DELTA
    
79.                  / DECODE (NVL (SQL.executions_delta, 0),
    
80.                            0, 1,
    
81.                            SQL.executions_delta)
    
82.                     "ROWs/exec"
    
83.             FROM dba_hist_sqlstat SQL, dba_hist_snapshot s
    
84.            WHERE     SQL.INSTANCE_NUMBER = s.INSTANCE_NUMBER
    
85.                  AND SQL.dbid = (SELECT dbid FROM v$database)
    
86.                  AND s.snap_id = SQL.snap_id
    
87.                  AND sql_id IN ('9hfkh0vxd9wq0'))
    
88. ORDER BY source, begin_time DESC;
    

复制代码

bayannur

Maclean Liu(刘相兵 发表于 2014-8-19 10:43

谢谢刘大，需要的sql结果已经放到附件里了。
sorry还有一点忘记说了，数据库在9点时候重启过，

Maclean Liu(刘相兵

4.dba_hist_sqlstat实例号:1                                        9hfkh0vxd9wq0      1655445474 2014-08-19 09:08:56                    2014-08-19 09:19:03      109959 75.6540711  .000163755   .0002213 .000291018 .003801417
4.dba_hist_sqlstat实例号:1                                        9hfkh0vxd9wq0      1655445474 2014-08-19 07:00:59                    2014-08-19 08:00:43      393955 339.305558  .013693348 5.66697299          0 .005650392
4.dba_hist_sqlstat实例号:1                                        9hfkh0vxd9wq0      1655445474 2014-08-19 06:00:31                    2014-08-19 07:00:59      739885 124.089669  .001426166 .368251599          0 .001320475
4.dba_hist_sqlstat实例号:1                                        9hfkh0vxd9wq0      1655445474 2014-08-19 05:00:01                    2014-08-19 06:00:31      709340 37.1994953   .00014308 .043253331          0 .000360899



2014-08-19 07:00:59                    2014-08-19 08:00:43  时间段该SQL 的单次执行时间 上升到 5.66697299 秒 /每次 ，但执行计划似乎无变化

Maclean Liu(刘相兵

执行

@?/rdbms/admin/awrsqrpt

时间为 需求为 2014-08-19 07:00:59                    2014-08-19 08:00:43


另查询

dba_hist_active_sess_history  where SAMPLE_TIME 在 8 点 到 9点

将结果保存到 excel 上传

Maclean Liu(刘相兵

Event        Waits        Time(s)        Avg Wait(ms)        % Total Call Time        Wait Class
latch: cache buffers chains        1,670,081        2,107,649        1,262        68.8        Concurrency
buffer busy waits        600,305        378,629        631        12.4        Concurrency
log file sync        1,042,403        97,813        94        3.2        Commit
latch free        41,983        89,936        2,142        2.9        Other
latch: library cache lock        7,300        69,653        9,542        2.3        Concurrency


转换思路， 就当时看 IO 很差 db file scattered read 平均等待173 ms  ，


Operating System Statistics
Statistic        Total
BUSY_TIME        2,152,321
IDLE_TIME        9,154,963
IOWAIT_TIME        2,853,599
NICE_TIME        0
SYS_TIME        2,035,768
USER_TIME        105,703
LOAD        47
RSRC_MGR_CPU_WAIT_TIME        0
VM_IN_BYTES        1.2E+11
VM_OUT_BYTES        20,786,733,056
PHYSICAL_MEMORY_BYTES        67,484,499,968
NUM_CPUS        32
NUM_CPU_SOCKETS        2


对比 Operating System Statistics 可以发现IOWAIT_TIME 和 VM_IN_BYTES 换页多了很多

Maclean Liu(刘相兵

需要osw 日志进一步诊断，否则该问题 可以判定为 原因不明的 操作系统资源问题， 包括 内存换页紧张和 IO变差

bayannur

Maclean Liu(刘相兵 发表于 2014-8-19 11:12
执行

@?/rdbms/admin/awrsqrpt

已上传相关文件

Maclean Liu(刘相兵

bayannur 发表于 2014-8-19 11:28
已上传相关文件

见7楼和8楼

bayannur

Maclean Liu(刘相兵 发表于 2014-8-19 11:19
需要osw 日志进一步诊断，否则该问题 可以判定为 原因不明的 操作系统资源问题， 包括 内存换页紧张和 IO变 ...

这个机器竟然没装osw。。。我马上去装一个，没准下次有用

bayannur

Maclean Liu(刘相兵 发表于 2014-8-19 11:30
见7楼和8楼

谢刘大，我只有再观察了

harryzhang

linux的话， sar 一下，会拉出今天的。
sar -u
sar -p
貌似一堆参数~~

bayannur

harryzhang 发表于 2014-8-19 14:03
linux的话， sar 一下，会拉出今天的。
sar -u
sar -p

谢谢提醒，今天7点多idle确实有点不一样，这种情况接下去该怎么分析呢。
[oracle@db ~]$ sar -u
Linux 2.6.32-358.el6.x86_64 (db)  08/19/2014      _x86_64_        (32 CPU)

12:00:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
07:00:02 AM     all      1.06      0.00      3.46      8.53      0.00     86.96
07:10:03 AM     all      0.98      0.00     20.74     24.06      0.00     54.23
07:22:47 AM     all      0.65      0.00     51.78     37.55      0.00     10.02
07:30:02 AM     all      0.48      0.00     14.87     16.65      0.00     68.00
07:40:14 AM     all      0.54      0.00      8.37     32.67      0.00     58.41
07:50:03 AM     all      1.33      0.00      4.32     20.38      0.00     73.97
08:00:03 AM     all      1.42      0.00      4.03     14.11      0.00     80.44
08:10:07 AM     all      1.17      0.00      5.13     34.01      0.00     59.69
08:20:03 AM     all      1.23      0.00     12.97     31.36      0.00     54.44
08:30:03 AM     all      1.41      0.00     15.88     21.18      0.00     61.53
08:40:13 AM     all      1.58      0.00      3.35     15.18      0.00     79.89
09:00:01 AM     all      0.50      0.00      8.52     39.24      0.00     51.73
09:10:01 AM     all      0.13      0.00      0.16      2.61      0.00     97.10
09:20:01 AM     all      0.99      0.00      0.45      0.13      0.00     98.43
09:30:01 AM     all      1.34      0.00      0.36      0.06      0.00     98.25
09:40:02 AM     all      1.41      0.00      0.35      0.05      0.00     98.19
09:50:01 AM     all      1.39      0.00      0.34      0.04      0.00     98.23
Average:        all      1.18      0.00      3.54      6.81      0.00     88.47
[oracle@db ~]$ sar -p
Linux 2.6.32-358.el6.x86_64 (db)  08/19/2014      _x86_64_        (32 CPU)

12:00:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
07:00:02 AM     all      1.06      0.00      3.46      8.53      0.00     86.96
07:10:03 AM     all      0.98      0.00     20.74     24.06      0.00     54.23
07:22:47 AM     all      0.65      0.00     51.78     37.55      0.00     10.02
07:30:02 AM     all      0.48      0.00     14.87     16.65      0.00     68.00
07:40:14 AM     all      0.54      0.00      8.37     32.67      0.00     58.41
07:50:03 AM     all      1.33      0.00      4.32     20.38      0.00     73.97
08:00:03 AM     all      1.42      0.00      4.03     14.11      0.00     80.44
08:10:07 AM     all      1.17      0.00      5.13     34.01      0.00     59.69
08:20:03 AM     all      1.23      0.00     12.97     31.36      0.00     54.44
08:30:03 AM     all      1.41      0.00     15.88     21.18      0.00     61.53
08:40:13 AM     all      1.58      0.00      3.35     15.18      0.00     79.89
09:00:01 AM     all      0.50      0.00      8.52     39.24      0.00     51.73
09:10:01 AM     all      0.13      0.00      0.16      2.61      0.00     97.10
09:20:01 AM     all      0.99      0.00      0.45      0.13      0.00     98.43
09:30:01 AM     all      1.34      0.00      0.36      0.06      0.00     98.25
09:40:02 AM     all      1.41      0.00      0.35      0.05      0.00     98.19
09:50:01 AM     all      1.39      0.00      0.34      0.04      0.00     98.23
Average:        all      1.18      0.00      3.50      6.73      0.00     88.59

dla001

%iowait   最高39.24%  ，问题出在IO上。  如果每天都是这个时段IO负载特别高，其它的时间没有问题的话，要看看这个时间段出现了什么问题。有没有其它的程序导致IO负载特别高。

bayannur

dla001 发表于 2014-8-21 09:40
%iowait   最高39.24%  ，问题出在IO上。  如果每天都是这个时段IO负载特别高，其它的时间没有问题的话，要 ...

不是每天都这个时候iowait高。以下是今天iowait比较高的时段，其他时候都低于1%。我打算搞个大叶和内存自动管理，看看是不是还有问题。
12:00:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
01:20:01 AM     all      1.04      0.00      0.26      0.02      0.00     98.68
01:30:01 AM     all      3.46      0.00      0.67     16.05      0.00     79.82
01:40:01 AM     all      5.10      0.00      0.95     10.37      0.00     83.58

saup007

我们以前遇到过。当然环境是这样的。

A库，偶尔出现负载很高，session越积累越多，超过参数的session或process，监听挂起。此时此时连接服务器都困难，连接上，看到内存换页占cpu排行前3.

找了很久原因，因为A库的SQL，使用dblink调用B库的表（B库是统计库，表很大），导致B库大量数据到A库运算，导致A库内存换页严重，热数据被换出buffer，来来回回搞几次，机器就不行了。

最后使用hints提示 /*+driving_site(main)*/，在B库运算结果，返回A库解决了。

-------------------------

LZ可考虑是不是大数据量的问题SQL导致。

不从oracle上找，与开发或业务沟通找找原因。

bayannur

saup007 发表于 2014-8-22 17:13
我们以前遇到过。当然环境是这样的。

A库，偶尔出现负载很高，session越积累越多，超过参数的session或pro ...

谢谢你的提醒。
我查了这个数据库没有建立dblink。
昨晚凌晨(周日1:00)的时候又报session数超了，有4000多的session，数据库最大的session数是4450。平时稳定的session数是2100左右。凌晨1点有执行导历史表的操作。
我怀疑有可能是到历史表阻塞了大部分的sql。这个库真是问题多多，最大的原因我觉得还是开发开了好多线程不断的扫某几个表，造成了session数达到2000多。
关于高并发的数据库需要注意什么参数，或是需要怎么优化(减少线程数开发人员不会同意)。有没有可参考的案例啊？从这方面也许能解决这个库的性能问题。

renjixinchina

12:00:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
07:22:47 AM     all      0.65      0.00     51.78     37.55      0.00     10.02

%system 最高达51.78 应该是换页引起的
64G 内存 配置了hugepage?

bayannur

renjixinchina 发表于 2014-8-25 15:08
12:00:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
07:22:47 AM     all ...

出现这个问题之前不是大叶，现在已经改成大叶了。
改了大叶之后暂时没有出现1楼的问题，但是又出现了超出session数的问题。
没改大叶之前没出现超session数，而是直接load飚到100多。。。

renjixinchina

那就增大sessions 但是一定留够足够的内存给系统
因为一个linux 进程按照4M来计算 5000个进程需要5000*4M/1024=19G
如果内存不够高并发时依然会出现换页问题

bayannur

renjixinchina 发表于 2014-8-25 15:57
那就增大sessions 但是一定留够足够的内存给系统
因为一个linux 进程按照4M来计算 5000个进程需要5000*4M/1 ...

好的，session数已经增到4400了。
对于并发量大的数据库，有什么有针对性的优化建议吗？