1

捕获问题SQL解决过度CPU消耗问题

Eygle 2019-07-24
38
摘要:捕获问题SQL解决过度CPU消耗问题

在生产环境中,我们可能会经常遇到CPU过度使用而影响系统性能或正常运行的问题。大多数情况下,系统的性能问题都是由不良SQL代码引起的,那么作为DBA,怎样发现和解决这些SQL问题就显得尤为重要。

 

本案例的系统环境为:

操作系统: Solaris8  数据库版本: 8.1.7.4

 

问题描述:业务及开发人员报告系统运行缓慢,已经影响业务系统正常使用。请求协助诊断。

9.2.1 使用vmstat检查系统当前情况

首先登陆数据库主机,检查当前系统状况。

使用vmstat检查,发现CPU资源已经耗尽,大量任务位于运行队列:

bash-2.03$ vmstat 3
 procs     memory            page            disk          faults      cpu
 r b w   swap  free  re  mf pi po fr de sr s6 s9 s1 sd   in   sy   cs us sy id
 0 0 0 5504232 1464112 0  0  0  0  0  0  0  0  1  1  0 4294967196 0 0 -84 -5 -145
 131 0 0 5368072 1518360 56 691 0 2 2 0  0  0  1  0  0 3011 7918 2795 97  3  0
 131 0 0 5377328 1522464 81 719 0 2 2 0  0  0  1  0  0 2766 8019 2577 96  4  0
 130 0 0 5382400 1524776 67 682 0 0 0 0  0  0  0  0  0 3570 8534 3316 97  3  0
 134 0 0 5373616 1520512 127 1078 0 2 2 0 0 0  1  0  0 3838 9584 3623 96  4  0
 136 0 0 5369392 1518496 107 924 0 5 5 0 0  0  0  0  0 2920 8573 2639 97  3  0
 132 0 0 5364912 1516224 63 578 0 0 0 0  0  0  0  0  0 3358 7944 3119 97  3  0
 129 0 0 5358648 1511712 189 1236 0 0 0 0 0 0  0  0  0 3366 10365 3135 95 5  0
 129 0 0 5354528 1511304 120 1194 0 0 0 0 0 0  0  4  0 3235 8864 2911 96  4  0

对于vmstat的用法及输出,简要说明一下:vmstat是Unix上一个常用的工具,可以帮助我们查看系统内存及CPU使用情况。

Vmstat最常用的两个参数是 t [n]:

t 表示采样间隔

n 表示采样次数

例如:vmstat 5 5,表示在T(5)秒时间内进行N(5)次采样。

对于前三列procs输出,分别代表以下含义:

r-->指运行队列中的进程数,如果这个参数经常超过CPU数量可能说明CPU存在瓶颈

b-->因为IO被Block的进程数

w-->idle的被swap的进程数

最后一项CPU标识系统CPU资源的分配和使用情况,最后一列Idle值通常被用来衡量系统CPU的空闲情况。

本案例当时,系统CPU资源已经耗尽,Idle为0,并且运行队列大量进程排队等待。

使用Top工具辅助诊断

通过Top工具,可以查看进程CPU耗用情况,如果存在进程异常,可以通过Top定位,为进一步诊断提供依据。对于本案例,观察进程CPU耗用,发现没有明显过高CPU使用的进程。

$ top
 
last pid: 28313;  load averages: 99.90, 117.54, 125.71            23:28:38
296 processes: 186 sleeping, 99 running, 2 zombie, 9 on cpu
CPU states:  0.0% idle, 96.5% user,  3.5% kernel,  0.0% iowait,  0.0% swap
Memory: 4096M real, 1404M free, 2185M swap in use, 5114M swap free
 
   PID USERNAME THR PRI NICE  SIZE   RES STATE    TIME    CPU COMMAND
 27082 oracle8i   1  33    0 1328M 1309M run      0:17  1.29% oracle
 26719 oracle8i   1  55    0 1327M 1306M sleep    0:29  1.11% oracle
 28103 oracle8i   1  35    0 1327M 1304M run      0:06  1.10% oracle
 28161 oracle8i   1  25    0 1327M 1305M run      0:04  1.10% oracle
 26199 oracle8i   1  45    0 1328M 1309M run      0:42  1.10% oracle
 26892 oracle8i   1  33    0 1328M 1310M run      0:24  1.09% oracle
 27805 oracle8i   1  45    0 1327M 1306M cpu/1    0:10  1.04% oracle
 23800 oracle8i   1  23    0 1327M 1306M run      1:28  1.03% oracle
 25197 oracle8i   1  34    0 1328M 1309M run      0:57  1.03% oracle

从Top的输出中我们发现有大量进程处于running的运行状态,CPU消耗很平均,单进程消耗大约在1%左右,基本可以排除个别进程异常导致CPU问题的可能(关于单进程异常CPU消耗问题可以参考第四章中的解决方法)。

检查进程数量

对于一个生产数据库系统,稳定运行的进程数量通常是可知的。

提示:对于稳定运行的生产系统,数据库的运行状况通常是稳定的,如果你绘制出性能曲线,你会发现每个星期的曲线几乎是可以重合的,对数据库系统的运行状况及性能指标具有充分认识和了解是必须的。

看一下当前系统的进程数量,从而进行比较判断:

bash-2.03$ ps -ef|grep ora|wc -l
     258
bash-2.03$ ps -ef|grep ora|wc -l
     275
bash-2.03$ ps -ef|grep ora|wc -l
     274
bash-2.03$ ps -ef|grep ora|wc -l
     278
bash-2.03$ ps -ef|grep ora|wc -l
     277
bash-2.03$ ps -ef|grep ora|wc -l
     366

发现此时系统存在大量Oracle进程,大约在300左右,大量进程消耗了几乎所有CPU资源,而正常情况下Oracle连接数应该在100左右。由此,可以做出基本判断,是数据库或应用出现问题,导致进程任务无法完成,不断累积,从而出现大量队列等待。

这些等待在数据库中应该有具体的体现,接下来需要登陆数据库进行检查了。

 登陆数据库

我们判断数据库可能经历了等待,那么Oracle数据库提供了相关视图供我们查询和发现问题,v$session_wait是首先值得我们关注的。查询v$session_wait获取各进程等待事件:

SQL> select sid,event,p1,p1text from v$session_wait;
       SID EVENT                                  P1 P1TEXT
---------- ------------------------------ ---------- -------------------------------
       124 latch free                     1.6144E+10 address
         1 pmon timer                            300 duration
         2 rdbms ipc message                     300 timeout
     。。。。。。
       140 buffer busy waits                      17 file#
        66 buffer busy waits                      17 file#
        10 db file sequential read                17 file#
        18 db file sequential read                17 file#
        54 db file sequential read                17 file#
        49 db file sequential read                17 file#
        48 db file sequential read                17 file#
        46 db file sequential read                17 file#
        45 db file sequential read                17 file#
。。。。。。
       234 db file sequential read                17 file#
       233 db file sequential read                17 file#
       230 db file sequential read                17 file#
       333 db file sequential read                17 file#
       330 db file scattered read                 17 file#
       310 db file scattered read                 17 file#
。。。。。。。
 
244 rows selected.

    

对于本案例,我们发现存在大量db file scattered read及db file sequential read等待。显然全表扫描等操作成为系统最严重的性能影响因素。

捕获相关SQL

确定这些进程因为数据访问产生了等待,我们考虑捕获这些SQL以发现问题。

这里用到了我的以下脚本getsqlbysid.sql,该脚本通过已知session的sid,联合v$session、v$sqltext视图,获得相关session正在执行的完整的SQL语句。

SELECT   sql_text
    FROM v$sqltext a
   WHERE a.hash_value = (SELECT sql_hash_value
                           FROM v$session b
                          WHERE b.SID = '&sid')
ORDER BY piece ASC
/

使用该脚本,通过从v$session_wait中获得的等待全表或索引扫描的进程SID,可以捕获可能存在问题的sql语句:

SQL> @getsqlbysid
Enter value for sid: 18
old   5: where b.sid='&sid'
new   5: where b.sid='18'
 
SQL_TEXT
----------------------------------------------------------------
select i.vc2title,i.numinfoguid  from  hs_info i where i.intenab
ledflag = 1  and i.intpublishstate = 1  and i.datpublishdate <=
sysdate  and i.numcatalogguid = 2047 order by i.datpublishdate d
esc, i.numorder desc

对几个进程进行跟踪,分别得到以上SQL语句,这些SQL可能就是问题产生的根源(以上语句如果良好编码应该使用绑定变量,但是目前这个不是我们关心的)。

使用该应用用户连接,通过autotrace功能检查以上SQL的执行计划:

SQL> set autotrace trace explain
SQL> select i.vc2title,i.numinfoguid  
  2  from  hs_info i where i.intenabledflag = 1  
  3  and i.intpublishstate = 1  and i.datpublishdate <=sysdate  
  4  and i.numcatalogguid = 3475
  5  order by i.datpublishdate desc, i.numorder desc  ;
Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE (Cost=228 Card=1 Bytes=106)
   1    0   SORT (ORDER BY) (Cost=228 Card=1 Bytes=106)
   2    1     TABLE ACCESS (FULL) OF 'HS_INFO' (Cost=218 Card=1 Bytes=106)
SQL> select count(*) from hs_info;
  COUNT(*)
----------
    227404

通过执行计划,我们看到以上查询使用了全表扫描,而该表这里有22万记录,全表扫描已经不再适合。通常对于小表,Oracle建议通过全表扫描进行数据访问,对于大表则应该通过索引以加快数据查询,当然如果查询要求返回表中大部分或者全部数据,那么全表扫描可能仍然是最好的选择。

从V$SYSSTAT视图中,我们可以查询得到关于全表扫描的系统统计信息:

SQL> col name for a30
SQL> select name,value from v$sysstat
  2  where name in ('table scans (short tables)','table scans (long tables)');
 
NAME                         VALUE
------------------------------           ----------
table scans (short tables)            828
table scans (long tables)             101

其中table scans (short tables)指对于小表的全表扫描的此时;table scans (long tables)指对于大表的全表扫描的次数。从Statspack的报告中,我们也可以找到这部分信息:

Instance Activity Stats for DB: CELLSTAR  Instance: ora8i  Snaps:      20 -   
Statistic                                    Total   per Second    per Trans  
--------------------------------- ---------------- ------------ ------------  
。。。。。。
table scan blocks gotten                38,228,349         37.0         26.9  
table scan rows gotten                 546,452,583        528.9        383.8  
table scans (direct read)                    5,784          0.0          0.0  
table scans (long tables)                    5,990          0.0          0.0  
table scans (rowid ranges)                   5,850          0.0          0.0  
table scans (short tables)               1,185,275          1.2           0.8

通常,如果一个数据库的table scans (long tables)过多,那么db file scattered read等待事件可能同样非常显著,和以上数据来自同一个report的Top5等待事件就是如此:

Top 5 Wait Events                                                             
~~~~~~~~~~~~~~~~~                                    Wait     % Total
Event                                         Waits  Time (cs)   Wt Time
-------------------------------------------- ------------ ------------ -------
log file parallel write                         1,436,993    1,102,188   10.80
log buffer space                                   16,698      873,203    8.56
log file sync                                   1,413,374      654,587    6.42
control file parallel write                       329,777      510,078    5.00
db file scattered read                            425,578      132,537    1.30

数据库内部,很多信息和现象都是紧密相关的,只要我们加深对于数据库的了解,在优化和诊断数据库问题时就能够得心应手。

Oracle通过一个内部参数_small_table_threshold来定义大表和小表的界限。缺省的该参数等于2%的Buffer数量,如果表的大小小于该参数定义,Oracle认为该表为小表,否则Oracle认为该表为大表。我们看一下Oracle9iR2中的情况:

SQL> @GetParDescrb.sql
Enter value for par: small
old   6:    AND x.ksppinm LIKE '%&par%'
new   6:    AND x.ksppinm LIKE '%small%'
NAME                           VALUE      DESCRIB
------------------------------ ---------- -----------------------------------
_small_table_threshold         200        threshold level of table size for direct reads

以上数据库中,200正好约为Buffer数量的2%:

SQL> show parameter db_cache_size
NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_cache_size                        big integer 83886080
SQL> select (83886080/8192)*2/100 from dual;
(83886080/8192)*2/100
---------------------
                204.8

所以要区分大小表(Long/Short)是因为全表扫描可能引起Buffer Cache的抖动,缺省的大表的全表扫描会被置于LRU的末端,以期尽快老化,减少Buffer的占用。从Oracle8i开始,Oracle的多缓冲池管理技术(Default/Keep/Recycle池)给了我们另外一个选择,对于不同大小、不同使用频率的数据表,从建表之初就可以指定其存储Buffer,以使得内存使用更加有效。

让我们继续以上的案例,在实际处理中,我们检查全表扫描的数据表,发现存在以下索引:

SQL> select index_name,index_type  from user_indexes where table_name='HS_INFO';
 
INDEX_NAME                     INDEX_TYPE
------------------------------ ---------------------------
HSIDX_INFO1                    FUNCTION-BASED NORMAL
HSIDX_INFO_SEARCHKEY        DOMAIN
PK_HS_INFO                     NORMAL

检查索引键值:

SQL> select index_name,column_name
    2 from user_ind_columns  where table_name ='HS_INFO';
INDEX_NAME                     COLUMN_NAME
------------------------------ --------------------
HSIDX_INFO1                    NUMORDER
HSIDX_INFO1                    SYS_NC00024$
HSIDX_INFO_SEARCHKEY        VC2INDEXWORDS
PK_HS_INFO                     NUMINFOGUID
SQL> desc hs_info
 Name                              Null?    Type
 --------------------------------- -------- --------------------------------------------
 NUMINFOGUID                       NOT NULL NUMBER(15)
 NUMCATALOGGUID                    NOT NULL NUMBER(15)
 INTTEXTTYPE                       NOT NULL NUMBER(38)
 VC2TITLE                          NOT NULL VARCHAR2(60)
 VC2AUTHOR                    VARCHAR2(100)
 NUMPREVINFOGUID                            NUMBER(15)
 NUMNEXTINFOGUID                            NUMBER(15)
 NUMORDER                          NOT NULL NUMBER(15)
。。。。。

创建新的索引以消除全表扫描

检查发现在numcatalogguid字段上并没有索引,该字段具有很好的区分度,考虑在该字段创建索引以消除全表扫描。

SQL> create index hs_info_NUMCATALOGGUID on hs_info(NUMCATALOGGUID);
Index created.
SQL> set autotrace trace explain
SQL> select i.vc2title,i.numinfoguid  
  2  from  hs_info i where i.intenabledflag = 1  
  3  and i.intpublishstate = 1  and i.datpublishdate <=sysdate  
  4  and i.numcatalogguid = 3475
  5  order by i.datpublishdate desc, i.numorder desc ;
 
Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE (Cost=12 Card=1 Bytes=106)
   1    0   SORT (ORDER BY) (Cost=12 Card=1 Bytes=106)
   2    1     TABLE ACCESS (BY INDEX ROWID) OF 'HS_INFO' (Cost=2 Card=1 Bytes=106)
   3    2       INDEX (RANGE SCAN) OF 'HS_INFO_NUMCATALOGGUID' (NON-UNIQUE) (Cost=1 Card=1)

观察系统状况

原大量等待消失

SQL> select sid,event,p1,p1text from v$session_wait where event not like 'SQL%';
 
       SID EVENT                                  P1 P1TEXT
---------- ------------------------------ ---------- ----------------------------------------------------------------
         1 pmon timer                            300 duration
         2 rdbms ipc message                     300 timeout
         3 rdbms ipc message                     300 timeout
         6 rdbms ipc message                  180000 timeout
        59 rdbms ipc message                    6000 timeout
       118 rdbms ipc message                    6000 timeout
       275 rdbms ipc message                   30000 timeout
       147 rdbms ipc message                    6000 timeout
        62 rdbms ipc message                    6000 timeout
        11 rdbms ipc message                   30000 timeout
         4 rdbms ipc message                     300 timeout
       305 db file sequential read                17 file#
       356 db file sequential read                17 file#
        19 db file scattered read                 17 file#
         5 smon timer                            300 sleep time
 
15 rows selected.

在另外的session里,持续观察的CPU使用情况:

bash-2.03$ vmstat 3
 procs     memory            page            disk          faults      cpu
 r b w   swap  free  re  mf pi po fr de sr s6 s9 s1 sd   in   sy   cs us sy id
 34 0 0 5343016 1465416 44 386 77 0 0 0  0  0  0  0  0 3197 8486 2902 92  8  0
 31 0 0 5331568 1459696 178 1491 122 0 0 0 0 0 0  3  0 3237 9461 3005 89 11  0
 31 0 0 5317792 1453008 76 719 80 0 0 0  0  0  0  0  0 3292 8736 3025 93  7  0
 31 2 0 5311144 1449552 235 1263 69 2 2 0 0 0  1  0  0 3473 9535 3357 88 12  0
 25 0 0 5300240 1443920 108 757 18 2 2 0 0  0  1  1  0 2377 7876 2274 95  5  0
 19 0 0 5295904 1441840 50 377 0 0 0  0  0  0  0  1  0 1915 6598 1599 98  1  0

----以上为创建索引之前部分

----以下为创建索引之后部分,CPU使用率恢复正常

 procs     memory            page            disk          faults      cpu
 r b w   swap  free  re  mf pi po fr de sr s6 s9 s1 sd   in   sy   cs us sy id
0 0 0 4955872 1287136 737 6258 16 0 0 0 0  0  0  3  0 2890 11777 4432 44 12 44
 1 0 0 4887888 1256464 809 6234 8 2 2 0  0  0  0  2  0 2809 12066 4247 45 12 43
 0 0 0 4828912 1228200 312 2364 13 5 5 0 0  0  2  1  0 2410 6816 3492 38  6 57
 0 0 0 4856816 1240168 8 138 0  0  0  0  0  0  1  0  0 2314 4026 3232 34  4 62
 0 0 0 4874176 1247712 0 86  0  0  0  0  0  0  0  0  0 2298 3930 3324 35  2 63
 2 0 0 4926088 1270824 34 560 0 0  0  0  0  0  0  0  0 2192 4694 2612 29 16 55
 0 0 0 5427320 1512952 53 694 0 0  0  0  0  0  3  2  0 2443 5085 3340 33 12 55
 0 0 0 5509120 1553136 0 37  0  0  0  0  0  0  0  0  0 2309 3908 3321 35  1 64

至此,此问题得以解决。

 性能何以提高

回答这个问题似乎是多余的,我只想重申一点:

有效的降低SQL的逻辑读是SQL优化的基本原则之一。

我们来比较一下前后两种执行方式的逻辑读取及性能差异。

a. 全表扫描的性能

SQL> select i.vc2title,i.numinfoguid  
  2  from  hs_info i where i.intenabledflag = 1  
  3  and i.intpublishstate = 1  and i.datpublishdate <=sysdate  
  4  and i.numcatalogguid = 3475
  5  order by i.datpublishdate desc, i.numorder desc  ;
352 rows selected.
Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE (Cost=541 Card=1 Bytes=106)
   1    0   SORT (ORDER BY) (Cost=541 Card=1 Bytes=106)
   2    1     TABLE ACCESS (FULL) OF 'HS_INFO' (Cost=531 Card=1 Bytes=106)
Statistics
----------------------------------------------------------
          0  recursive calls
         25  db block gets
       3499  consistent gets
        258  physical reads
          0  redo size
…..
          2  sorts (memory)
          0  sorts (disk)
        352  rows processed

b. 使用索引的性能

SQL> select i.vc2title,i.numinfoguid  
  2  from  hs_info i where i.intenabledflag = 1  
  3  and i.intpublishstate = 1  and i.datpublishdate <=sysdate  
  4  and i.numcatalogguid = 3475
  5  order by i.datpublishdate desc, i.numorder desc;
352 rows selected.
 
Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE (Cost=12 Card=1 Bytes=106)
   1    0   SORT (ORDER BY) (Cost=12 Card=1 Bytes=106)
   2    1     TABLE ACCESS (BY INDEX ROWID) OF 'HS_INFO' (Cost=2 Card=1 Bytes=106)
   3    2       INDEX (RANGE SCAN) OF 'HS_INFO_NUMCATALOGGUID' (NON-UNIQUE) (Cost=1 Card=1)
Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
         89  consistent gets
          0  physical reads
          0  redo size
….
          1  sorts (memory)
          0  sorts (disk)
        352  rows processed

consistent gets从3499 到89,我们看到性能得到了巨大的提高.

 

结语:

通常,开发人员很少注意SQL代码的效率,他们更着眼于功能的实现。

至于性能问题通常被认为是次要的,而且在应用系统开发初期,由于数据库数据量较少,对于查询SQL语句等,不容易体会出各种SQL句法的性能差异。

但是一旦这些应用作为生产系统上线运行,随着数据库中数据量的增加,大量并发访问,系统的响应速度可能就会成为系统需要解决的最主要的问题之一。

在少量用户下性能可以接受的SQL,可能在大量用户并发的条件下就会成为性能瓶颈。

在我这个案例中,开发人员很难相信仅只一条SQL语句就导致了整个数据库的性能下降。然而事实就是如此,一条低效的SQL语句就可能毁掉你的数据库,所以在系统设计及开发过程中,你必须考虑到诸多细节,严格的测试也是提早发现问题的有效方法。

如果不幸以上环节都被忽略,那么,DBA(也许就是你)就是最后的一环,你必须能够快速的诊断并解决各种复杂问题。


「喜欢文章,快来给作者赞赏墨值吧」

评论

0
1
Oracle
订阅
欢迎订阅Oracle频道,订阅之后可以获取最新资讯和更新通知。
墨值排行
今日本周综合
近期活动
全部
相关课程
全部