定位Oracle数据库CPU暴增的步骤

原创三石 All China Database Union 2024-07-31

1076

1、发现问题

有套生产库的节点1，监控老是报警负载高，需要定位到底是什么问题。

2、定位问题

2.1、监控定位

早上8：30 到 11：30。

2.2、服务器定位

服务器负载

sar

08:20:01 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
08:30:01 AM     all     12.13      0.00      1.00      0.03      0.00     86.84
08:40:01 AM     all     14.43      0.00      1.19      0.03      0.00     84.35
08:50:01 AM     all     17.56      0.00      1.32      0.02      0.00     81.10
09:00:01 AM     all     17.99      0.00      1.30      0.01      0.00     80.69
09:10:01 AM     all     19.11      0.00      1.43      0.01      0.00     79.45
09:20:01 AM     all     17.65      0.00      1.30      0.02      0.00     81.03
09:30:01 AM     all     18.82      0.00      1.37      0.02      0.00     79.80
09:40:01 AM     all     18.30      0.00      1.28      0.02      0.00     80.40
09:50:01 AM     all     17.98      0.00      1.28      0.01      0.00     80.72
10:00:01 AM     all     17.61      0.00      1.30      0.01      0.00     81.08
10:10:01 AM     all     19.13      0.00      1.25      0.01      0.00     79.60
10:20:01 AM     all     17.55      0.00      1.57      0.02      0.00     80.86
10:30:02 AM     all     17.73      0.00      1.20      0.01      0.00     81.06
10:40:01 AM     all     18.37      0.00      1.25      0.01      0.00     80.36
10:50:01 AM     all     20.09      0.00      1.34      0.01      0.00     78.56
11:00:01 AM     all     19.50      0.00      1.36      0.01      0.00     79.12
11:10:01 AM     all     19.88      0.00      1.40      0.04      0.00     78.67
11:20:01 AM     all     19.80      0.00      1.38      0.03      0.00     78.78
11:30:01 AM     all     18.40      0.00      1.24      0.03      0.00     80.33

检查CPU

top
Shift + P

检查IO

[root ~]# yum install -y iotop

[root ~]# iotop -o -a

-o：只显示有IO操作的进程
-a：显示累积使用量

基本定位是CPU的问题。

2.3、数据库定位

根据服务器检查的负载高的时间来定位追踪数据库的问题。

2.3.1、SQL语句定位

检查某段时间范围内的等待事件

SELECT instance_number, event, COUNT(*)
  FROM dba_hist_active_sess_history
 WHERE sample_time BETWEEN
       to_date('2024-07-30 09:00', 'yyyy-mm-dd hh24:mi') AND
       to_date('2024-07-30 11:30', 'yyyy-mm-dd hh24:mi')
 HAVING(COUNT(*)) > 50
 GROUP BY instance_number, event
 ORDER BY 3 desc;

根据刚才排名最高的等待事件来定位sql语句

select sql_id,event,count(*) 
from dba_hist_active_sess_history 
where event in ('等待事件') 
group by sql_id,event 
having count(*)>10 order by 3 desc;

再根据以上的信息拼凑具体的节点、时间和等待事件，查出sql语句

SELECT event, user_id, sql_id, COUNT(*)
  FROM dba_hist_active_sess_history
 WHERE sample_time BETWEEN
       to_date('2024-07-30 09:00', 'yyyy-mm-dd hh24:mi') AND
       to_date('2024-07-30 11:30', 'yyyy-mm-dd hh24:mi')
   AND instance_number = 1
   AND event = '等待事件'
 GROUP BY user_id, event, sql_id
 ORDER BY 2;

但是我这里遇到了问题，就是我查的等待事件为空，但是统计的执行次数多的吓人！

2.3.2、数据库报告定位

我个人习惯性的喜欢先看ASH报告。

2.3.2.1、ASH报告

这些关键信息是空的。

2.3.2.2、AWR报告定位

负载：round ( DB Time / Elapsed / CPUs * 100 ) = 21.73%

每秒89个连接，每秒执行sql1165.2次。基本上可以判断是风暴链接的事情。

等待事件无异常

查看CPU主要是由用户使用。

后台等待事件发现日志写的比例较高。

SQL ordered by Elapsed Time

SQL ordered by CPU Time

SQL ordered by User I/O Wait Time

SQL ordered by Gets

SQL ordered by Reads

SQL ordered by Physical Reads (UnOptimized)

无异常SQL（特指占比较大的SQL）

SQL ordered by Executions

select /*+ connect_by_filtering */ privilege#, level from sysauth$ connect by grantee#=prior privilege# and privilege#>0 start with grantee#=:1 and privilege#>0
执行了 1828302 次

select value$ from props$ where name = 'GLOBAL_DB_NAME'
执行了 482674 次

select SYS_CONTEXT('USERENV', 'SERVER_HOST'), SYS_CONTEXT('USERENV', 'DB_UNIQUE_NAME'), SYS_CONTEXT('USERENV', 'INSTANCE_NAME'), SYS_CONTEXT('USERENV', 'SERVICE_NAME'), INSTANCE_NUMBER, STARTUP_TIME, SYS_CONTEXT('USERENV', 'DB_DOMAIN') from v$instance where INSTANCE_NAME=SYS_CONTEXT('USERENV', 'INSTANCE_NAME')
执行了 482202 次

SQL ordered by Parse Calls

select /*+ connect_by_filtering */ privilege#, level from sysauth$ connect by grantee#=prior privilege# and privilege#>0 start with grantee#=:1 and privilege#>0
执行 1828302 次，解析 1828418 次

select SYS_CONTEXT('USERENV', 'SERVER_HOST'), SYS_CONTEXT('USERENV', 'DB_UNIQUE_NAME'), SYS_CONTEXT('USERENV', 'INSTANCE_NAME'), SYS_CONTEXT('USERENV', 'SERVICE_NAME'), INSTANCE_NUMBER, STARTUP_TIME, SYS_CONTEXT('USERENV', 'DB_DOMAIN') from v$instance where INSTANCE_NAME=SYS_CONTEXT('USERENV', 'INSTANCE_NAME')
执行 482202 次，解析 482442 次

select value$ from props$ where name = 'GLOBAL_DB_NAME'
执行 482674 次，解析 482409 次

解析会引起CPU的暴增，而这么多系统的SQL语句，百度说是每次登录就会执行的默认SQL。

3、解决问题

3.1、解析监听日志

节点1

cd /u01/app/grid/diag/tnslsnr/AAAAA/listener/trace/listener.log

fgrep "30-JUL-2024 " listener.log|fgrep "establish"|awk -F* '{print $1 " " $3}'|awk -F= '{ print $1 " "  $4}'|sed -e 's/......$//g'| awk '{print $1 " " $2 " " $4}'|cut -b-14,21- |sort |uniq -c

第一列是次数，第二列是时间，第三列是IP。

节点2

cd /u01/app/grid/diag/tnslsnr/cwglrac12/listener/trace/

fgrep "30-JUL-2024 " listener.log|fgrep "establish"|awk -F* '{print $1 " " $3}'|awk -F= '{ print $1 " "  $4}'|sed -e 's/......$//g'| awk '{print $1 " " $2 " " $4}'|cut -b-14,21- |sort |uniq -c

两者之间互相对比

发现是由这些IP导致的连接连接风暴，而且节点1压倒性的超过节点2连接次数。

3.2、设置触发器

但是领导不满意，他的意思是这些服务器IP没法确切确定哪些应用用的。让我开审计，开玩笑，重启风险更大。

创建记录表。

create table db_logon_info
(
  logon_time      date,
  partition_id    char(2),
  instance_name   varchar2(16),
  session_user    varchar2(32),
  ip_address      varchar2(16),
  host            varchar2(64),
  os_user         varchar2(32),
  isdba           varchar2(6),
  BG_JOB_ID       number
);

赋予插入权限

select 'grant insert on db_logon_info to ' || username ||'; ' from dba_users t where account_status ='OPEN';

创建触发器


CREATE OR REPLACE TRIGGER tri_logon_log
  AFTER LOGON ON DATABASE
BEGIN
  if sys_context('USERENV', 'AUTHENTICATION_TYPE') <> 'OS' and
     sys_context('USERENV', 'SESSION_USER') <> 'SYS' then
    INSERT INTO db_logon_info
    values
      (sysdate,
       to_char(sysdate, 'MM'),
       sys_context('USERENV', 'INSTANCE_NAME'),
       sys_context('USERENV', 'SESSION_USER'),
       sys_context('USERENV', 'IP_ADDRESS'),
       sys_context('USERENV', 'HOST'),
       sys_context('USERENV', 'OS_USER'),
       sys_context('USERENV', 'ISDBA'),
       sys_context('USERENV', 'BG_JOB_ID'));
    commit;
  end if;
exception
  when others then
    null;
  
END;
/

这里多说一嘴，删除的顺序应该是先关闭或者删除触发器，然后再删除表，要不会触发报错，导致数据库无法使用。报错信息是 ORA-00604、 ORA-01438、 ORA-06512。

查询具体的连接应用信息。

select * from (
select SESSION_USER, IP_ADDRESS, HOST, count(*)
  from sys.db_logon_info
 where instance_name = '节点1' 
 group by SESSION_USER, IP_ADDRESS, HOST
 order by 4 desc)  where rownum <= 10;

这里就不放图了。

这里所有需要的信息都汇集了，去找开发人员干死他们吧。

人员对答：

开发：这个是连接次数还是同时连接个数？

我：就跟赵子龙七进七出一样，同一时间就一个赵子龙，但是进出频率极高。关键是，他连进来不执行业务sql语句，是个空连接，然后连进来就断开。

开发：明白了，我看看。

4、问题原理

4.1、Starce定位

查看数据库登录的启动过程

[oracle:/]$ strace -T -t -f -o /tmp/strace_slow.log sqlplus test/test

通过-f可以查到每个子进程启动耗费的时间。

但是没查到默认登陆执行的SQL语句。

5、总结

摆事实，讲道理，干死开发没没问题。

墨力计划

「喜欢这篇文章，您的关注和赞赏是给作者最好的鼓励」

关注作者

1人已赞赏