ITPub博客

首页 > 数据库 > Oracle > [20201007]exadata存储索引.txt

[20201007]exadata存储索引.txt

原创 Oracle 作者:lfree 时间:2020-01-08 08:40:25 0 删除 编辑

[20201007]exadata存储索引.txt

--//很久没有看生产系统的awr报表,昨天看了一下,发现一条语句有问题。
--//我现在看exadata服务器的awr报表一般先看Top 10 Foreground Events by Total Wait Time,然后直奔IO Stats与Segment Statistics 部分,看
--//IOStat by Function summary部分以及Segments by Direct Physical Reads部分。

IOStat by Filetype summary

'Data' columns suffixed with M,G,T,P are in multiples of 1024 other columns suffixed with K,M,G,T,P are in multiples of 1000
Small Read and Large Read are average service times, in milliseconds
Ordered by (Data Read + Write) desc

Filetype Name   Reads: Data   Reqs per sec  Data per sec  Writes: Data  Reqs per sec  Data per sec  Small Read    Large Read
Data File       1.4T          1000.91       406.292       1.8G          42.70         .509M         0.48          24.56
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Temp File       4.9G          9.66          1.384M        6.5G          9.03          1.834M        10.70         10.54
Log File        0M            0.00          0M            1.1G          107.90        .311M         3.50           
Control File    336M          5.94          .093M         80M           1.41          .022M         0.08           
Other           1M            0.27          0M            0M            0.00          0M            0.62           
TOTAL:          1.4T          1016.77       407.77M       9.5G          161.04        2.677M        0.59          24.45

--//注意看下划线Data per sec对应的是406.292,不知道什么原因没有单位(估计溢出了),估计应该是M,total部分也指示单位应该是M。
--//1.4*1024*1024/3600 = 407.779,基本相近。也就是每秒读取量已经达到400M/s。而且这个是平均值,如果是一般服务器,系统早就over了。
--//平均每次请求 406.292/1000.91 = .406M
--//另外我发现1点copy and paste的awr 的html文件这部分内容,设置set tabstop=16,基本不用对齐处理,可以参考链接:
--//http://blog.itpub.net/267265/viewspace-2216951/ => [20181019]vim小技巧删除制表符.txt

--//直接查看Segments by Direct Physical Reads:

Total Direct Physical Reads: 184,881,823
Captured Segments account for 97.9% of Total

Owner      Tablespace Name Object Name    Subobject Name Obj. Type Direct Reads %Total
XXXXXX_YYY XXXXXX_YYY      EMR_YZBCZRZ                   TABLE     166,492,107  90.05
....
--//这里设置:set tabstop=24,就可以实现对齐。注:行太长,我做了一些小处理。
--//很明显问题集中在表EMR_YZBCZRZ。但是当我在awr报表检索EMR_YZBCZRZ并没有发现对应sql语句。
--//检查也没有发现该表建立对应的视图,我在toad下sga trace检索EMR_YZBCZRZ,也没有看到对应的语句。
--//开始以为对应sql语句已经从共享池清除或者没有使用绑定变量仅仅执行1次。

> select object_id,data_object_id,last_ddl_time from dba_objects where object_name='EMR_YZBCZRZ';

 OBJECT_ID DATA_OBJECT_ID LAST_DDL_TIME
---------- -------------- -------------------
     93712          93712 2019-09-23 16:32:13
--//2019-09-23 16:32:13 改动过表结构。

> SELECT sql_id,count(*)
  FROM DBA_HIST_ACTIVE_SESS_HISTORY
 WHERE     sample_time BETWEEN TRUNC (SYSDATE - 1) + 10 / 24
                           AND TRUNC (SYSDATE - 1) + 11 / 24
       AND current_obj# = 93712
       group by sql_id order by 2 desc;

SQL_ID          COUNT(*)
------------- ----------
5yqm7qry03mcg          5
f8733rs2f3bng          1
39pbhs984wfnu          1

> @ sql_id f8733rs2f3bng
SQL_ID        SQLTEXT
------------- ------------------------
f8733rs2f3bng SELECT sysdate FROM Dual

--//奇怪有点不理解??另外1个语句39pbhs984wfnu也与表EMR_YZBCZRZ无关。有问题是sql_id='5yqm7qry03mcg'语句。
--//DBA_HIST_ACTIVE_SESS_HISTORY保存是10秒1个取样的情况,往大的估计也就是5*10=50秒。
--//查询当前9-10点的情况:
> SELECT count(*)
  FROM V$ACTIVE_SESSION_HISTORY
 WHERE     sample_time BETWEEN TRUNC (SYSDATE ) + 9 / 24
                           AND TRUNC (SYSDATE ) + 10 / 24
       AND current_obj# = 93712
       and sql_id='5yqm7qry03mcg';

  COUNT(*)
----------
        67

--//粗略估计67秒。估计这个时间总的消耗不大,在awr报表没有看到该语句。为什么在toad下sga trace检索EMR_YZBCZRZ没有发现呢?

> @ sql_id 5yqm7qry03mcg
old   1: select sql_id,sql_fulltext sqltext from gv$sqlarea where sql_id='&1'
new   1: select sql_id,sql_fulltext sqltext from gv$sqlarea where sql_id='5yqm7qry03mcg'
SQL_ID        SQLTEXT
------------- -----------------------------------------------------------------------------------------------
5yqm7qry03mcg WITH x AS (
                          ... --/trunc
                         )
                    SELECT x.*,y.xtsj
                     FROM x,emr_yzbczrz y WHERE x.yzbxh = y.yzbxh AND (y.czjs = 2 OR (y.czjs = 1 AND y.czlx = 5))  
                     and y.xtsj  >=to_date(:1,'yyyy-mm-dd hh24:mi:ss') and y.xtsj <=to_date(:2,'yyyy-mm-dd hh24:mi:ss')

> @desc v$sqlarea
      Name          Null?    Type
      ------------- -------- ----------------
    1 SQL_TEXT               VARCHAR2(1000)
    2 SQL_FULLTEXT           CLOB
    3 SQL_ID                 VARCHAR2(13)
...
--//才发现emr_yzbczrz在1000个字符之外,toad按照字串查询sql语句的缺点暴露出来,漏掉该sql语句。

> @ desc xxxxxx_yyy.emr_yzbczrz
           Name    Null?    Type
           ------- -------- --------------
.......
   10      XTSJ             DATE

--//很明显这个字段是"最近"添加上来的。

> set timing on
> select min(XTSJ) from emr_yzbczrz;
MIN(XTSJ)
-------------------
2019-09-23 16:32:14
Elapsed: 00:00:06.47

--//与查询dba_objects视图的LAST_DDL_TIME=2019-09-23 16:32:13,基本对上,也就是2019-09-23 16:32:13添加这个字段xtsj。
--//查询需要7秒,很明显这样取最小值的查询方式没有充分利用exadata的存储索引.更改如下:

> select min(XTSJ) from emr_yzbczrz where xtsj<='2019-09-23 16:32:15';
MIN(XTSJ)
-------------------
2019-09-23 16:32:14
Elapsed: 00:00:00.18
--//这样飞快。

--//获取绑定变量值看看:
> @ bind_cap 5yqm7qry03mcg ''
SQL_ID        CHILD_NUMBER WAS NAME POSITION MAX_LENGTH LAST_CAPTURED       DATATYPE_STRING VALUE_STRING        C30
------------- ------------ --- ---- -------- ---------- ------------------- --------------- ------------------- ----------------------
5yqm7qry03mcg            2 YES :1          1        128 2019-12-31 22:51:08 VARCHAR2(128)   2019-12-31 22:50:30
                           YES :2          2        128 2019-12-31 22:51:08 VARCHAR2(128)   2019-12-31 22:51:05
--//查询时间范围很小,2019-12-31 22:50:30 - 2019-12-31 22:51:05,仅仅范围在35秒.
--//我大概可以猜测开发的目的,也就显示在一个屏幕上不断刷新,估计是给某个领导查看,哈哈一点意思都没有.

> @ bind_cap_awr 5yqm7qry03mcg ''
   SNAP_ID SQL_ID        WAS LAST_CAPTURED       NAME POSITION MAX_LENGTH DATATYPE_STRING VALUE_STRING         C30
---------- ------------- --- ------------------- ---- -------- ---------- --------------- -------------------- -----------------------
........
     45520 5yqm7qry03mcg YES 2019-12-31 22:51:08 :1          1        128 VARCHAR2(128)   2019-12-31 22:50:30
                                                 :2          2        128 VARCHAR2(128)   2019-12-31 22:51:05
1442 rows selected.
--//这是我看到最大LAST_CAPTURED时间,也就是以后这条语句再也没有出现在awr报表。
--//很明显exadata的存储索引挥发极大的作用,掩盖问题的本质,如果你直接执行sql_id语句,仅仅不到1秒就完成了。

--//如果查询:
SELECT count(*)
  FROM V$ACTIVE_SESSION_HISTORY
 WHERE     sample_time BETWEEN TRUNC (SYSDATE ) + 9 / 24
                           AND TRUNC (SYSDATE ) + 10 / 24
       and sql_id='5yqm7qry03mcg';
count(*)
-------
67

--//仅仅显示67,对应67秒显然有点多,实际上每次执行不到0.5s上下 ,总共 0.5*67 = 34秒上下。

> set numw 12
> @ d_buffer 5yqm7qry03mcg 60
 EXECUTIONS1 BUFFER_GETS1 ELAPSED_TIME1 ROWS_PROCESSED1
------------ ------------ ------------- ---------------
       89718   4293590676   44928290360         1435349

1 row selected.

... sleep 60 , waiting ....

 EXECUTIONS2 BUFFER_GETS2 ELAPSED_TIME2 ROWS_PROCESSED2
------------ ------------ ------------- ---------------
       89720      1811045   44929438434         1435373

1 row selected.

总buffer_gets 每次buffer_gets 执行次数   总执行时间 每次执行时间 总处理记录数 平均处理记录数
------------- --------------- -------- ------------ ------------ ------------ --------------
  -4291779631     -2145889816        2      1148074       574037           24             12

1 row selected.
--//^_^,运气真不好,第一次看到统计信息溢出的情况,相减变成了负数.再做一次对比:

> @ d_buffer 5yqm7qry03mcg 60
 EXECUTIONS1 BUFFER_GETS1 ELAPSED_TIME1 ROWS_PROCESSED1
------------ ------------ ------------- ---------------
       89722      4999857   44930492814         1435496

1 row selected.

... sleep 60 , waiting ....

 EXECUTIONS2 BUFFER_GETS2 ELAPSED_TIME2 ROWS_PROCESSED2
------------ ------------ ------------- ---------------
       89724      8188024   44931515542         1435596

1 row selected.

总buffer_gets 每次buffer_gets 执行次数   总执行时间 每次执行时间 总处理记录数 平均处理记录数
------------- --------------- -------- ------------ ------------ ------------ --------------
      3188167       1594083.5        2      1022728       511364          100             50
1 row selected.
--//可以发现平均每次执行消耗511364微秒(单位是10^-6秒),相当于0.5秒。
--//1594084*8192/1024/1024/1024 = 12.16G,表EMR_YZBCZRZ大小就是11.9G,基本对上。


--//建立索引再测试:
CREATE INDEX XXXXXX_YYY.i_EMR_YZBCZRZ_XTSJ ON XXXXXX_YYY.EMR_YZBCZRZ
(XTSJ)
LOGGING
STORAGE    (
            BUFFER_POOL      DEFAULT
            FLASH_CACHE      DEFAULT
            CELL_FLASH_CACHE DEFAULT
           )
NOPARALLEL
ONLINE;

*
ERROR at line 1:
ORA-00604: error occurred at recursive SQL level 2
ORA-01031: insufficient privileges
ORA-06512: at line 13
ORA-00604: error occurred at recursive SQL level 2
ORA-01031: insufficient privileges
ORA-06512: at line 13
--//alert.log
Tue Jan 07 10:57:25 2020
online index (re)build cleanup: objn=151619 maxretry=2000 forever=0
--//奇怪,怎么会有出现这样的情况,居然出现2次报错.而且索引已经建立完成,至少可用.另外写一篇blog分析。我发现onlin建立索引时
--//SYS_JOURNAL_151619 IOT表没有删除,似乎在尝试2000次后报错.
--//注:我必须要online建立,不然影响业务,建立需要不到4分钟(不知道这2000次尝试占了多少时间)。

> @ d_buffer 5yqm7qry03mcg 60
 EXECUTIONS1 BUFFER_GETS1 ELAPSED_TIME1 ROWS_PROCESSED1
------------ ------------ ------------- ---------------
       89745     22989971   44942090061         1436189

1 row selected.
... sleep 60 , waiting ....
 EXECUTIONS2 BUFFER_GETS2 ELAPSED_TIME2 ROWS_PROCESSED2
------------ ------------ ------------- ---------------
       89747     23066613   44942854509         1436302
1 row selected.

总buffer_gets 每次buffer_gets     执行次数   总执行时间 每次执行时间 总处理记录数 平均处理记录数
------------- --------------- ------------ ------------ ------------ ------------ --------------
        76642           38321            2       764448       382224          113           56.5
1 row selected.
--//使用.38秒,仅仅节约一点点时间,像这种情况是建立索引还是不需要建立索引非常纠结。
--//做这样优化非常没有成就感,我大概节省了 (0.511-0.382)*67 = 8.643 秒,感觉跟没做没有什么区别。

总结:
1.很久不看awr报表,有点生疏,排除问题走了一个大大的弯路。
2.正好通过toad检索没有发现问题sql语句,又走了一个弯路。
3.exadate 我个人观点就是就是一些垃圾系统的保护伞,试想如果这样的系统在迁回非exadata系统时,如果没有发现问题语句。
  这样的系统能用才怪。实际上还有更多的语句被exadata的优异IO性能掩盖无法暴露出来。
4.像这样的索引是建立还是不建立,我自己心里也非常纠结。
5.而且像这样的语句awr报表居然漏掉,有点意外。看来给修改awr收集信息设置:http://blog.itpub.net/267265/viewspace-2217432/
6.不知道今天是否运气不好,居然看到BUFFER_GETS溢出的情况.
--// buffer_gets 最大应该是 2^32-1 = 4294967295.
--//(4294967295-4293590676+1811045 )/2 = 1593832
--//1593832*8192/1024/1024/1024 = 12.12G.
7.不到半个小时再看,我发现SYS_JOURNAL_151619 IOT表已经删除,我建立的索引已经不见,估计回滚了.不过我已经大概知道问题的原因,
  去年上半年购买的一个防水墙产品造成的问题,另写一篇文章描述该问题.
8.今天不知道什么原因,许多事情非常不顺,是否天气太热27度。年关快到,做事情一定不要浮躁,要小心小心再小心。

--//附上测试脚本:
$ cat d_buffer.sql
col executions1 new_value x1
col buffer_gets1 new_value x2
col ELAPSED_TIME1 new_value x3
col ROWS_PROCESSED1 new_value x4

col executions2 new_value y1
col buffer_gets2 new_value y2
col ELAPSED_TIME2 new_value y3
col ROWS_PROCESSED2 new_value y4

col var3 new_value var3

select executions executions1,buffer_gets buffer_gets1,elapsed_time elapsed_time1,rows_processed rows_processed1  from v$sqlarea where sql_id='&&1';

prompt ... sleep &&2 , waiting ....
host sleep &&2

select executions executions2,buffer_gets buffer_gets2,elapsed_time elapsed_time2 ,rows_processed rows_processed2 from v$sqlarea where sql_id='&&1';

select &y2-&x2 "总buffer_gets", (&y2-&x2)/(&y1-&x1) "每次buffer_gets",&y1- &x1 "执行次数" , &y3-&x3 "总执行时间", (&y3-&x3)/(&y1-&x1) "每次执行时间" , &y4-&x4 "总处理记录数",(&y4-&x4)/(&y1-&x1) "平均处理记录数" from dual ;

$ cat bind_cap.sql
set verify off
column value_string format a50
column datatype_string format a15
break on sql_id on child_number  skip 1
select  replace(sql_fulltext,chr(13),'') c200 from v$sql where sql_id='&1' and rownum<=1;

SELECT sql_id,
       child_number,
       was_captured,
       name,
       position,
       max_length,
       last_captured,
       datatype_string,
       DECODE (
          datatype_string,
          'DATE', TO_CHAR (TO_DATE (value_string, 'mm/dd/yy hh24:mi:ss'),
                           'yyyy/mm/dd hh24:mi:ss'),
          value_string)
          value_string,
          decode(datatype_string,'TIMESTAMP',ANYDATA.accesstimestamp (value_anydata)) c30
  FROM v$sql_bind_capture
 WHERE sql_id = '&1' and was_captured='YES' and  DUP_POSITION is null and name=nvl('&&2',name)
 order by child_number,was_captured,position;
break on sql_id on child_number  skip 0

$ cat bind_cap_awr.sql
set verify off
prompt
prompt @bind_cap_awr sql_id [column]
prompt
column value_string format a50
column datatype_string format a15
break on snap_id on sql_id on was_captured on last_captured skip 1

select  replace(sql_fulltext,chr(13),'') c200 from v$sql where sql_id='&1' and rownum<=1;
--select  replace(sql_text,chr(13),'') c200 from DBA_HIST_SQLTEXT where sql_id='&1' and rownum<=1;

SELECT snap_id,
         sql_id,
         was_captured,
         last_captured,
         name,
         position,
         max_length,
         datatype_string,
         DECODE (
            datatype_string,
            'DATE', TO_CHAR (TO_DATE (value_string, 'mm/dd/yy hh24:mi:ss'),
                             'yyyy/mm/dd hh24:mi:ss'),
            value_string)
            value_string,
            decode(datatype_string,'TIMESTAMP',ANYDATA.accesstimestamp (value_anydata)) c30
    FROM DBA_HIST_SQLBIND
   WHERE sql_id = '&1' AND was_captured = 'YES' and  dup_position is null and name=nvl('&&2',name)
ORDER BY snap_id ,last_captured, was_captured, position;
break on snap_id on sql_id on was_captured on last_captured skip 0

来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/267265/viewspace-2672368/,如需转载,请注明出处,否则将追究法律责任。

请登录后发表评论 登录
全部评论
熟悉oracle相关技术,擅长sql优化,rman备份与恢复,熟悉linux shell编程。

注册时间:2008-01-03

  • 博文量
    2599
  • 访问量
    6371725