找回密码
 立即注册
首页 业界区 业界 Oracle故障处理:分析Oracle数据库离奇的多快读慢 ...

Oracle故障处理:分析Oracle数据库离奇的多快读慢

呼延冰枫 2025-6-22 20:00:45
我们的文章会在微信公众号IT民工的龙马人生和博客网站( www.htz.pw )同步更新 ,欢迎关注收藏,也欢迎大家转载,但是请在文章开始地方标注文章出处,谢谢!
由于博客中有大量代码,通过页面浏览效果更佳。
1 环境介绍与现象描述

数据库多块读很慢,单块读、写都很正常,多块读的平均响应时间是单块都的10倍。
本系统数据文件存放在VXFS上面,数据库是从9i通过DG方式升级到11G,9i使用的是raw.
2 分析与测试过程

2.1 AWR中收集单块读与多块读的平均响应时间

下面是从AWR中统计每个快照的单块读与多块读的响应时间
  1. SQL> col EVENT_NAME for a30
  2. SQL> col total_waits for 99999999999999
  3. SQL> col total_time_s for 999999999.999
  4. SQL> col avg_time_ms for 999999999.999
  5. SQL> BREAK ON inst SKIP 1
  6. SQL> select instance_number inst,
  7.   2         to_char(time, 'YYYY-MM-DD HH24:MI:SS') time,
  8.   3         event_name,
  9.   4         sum(delta_total_waits) total_waits,
  10.   5         round(sum(delta_time_waited / 1000000), 3) total_time_s,
  11.   6         round(sum(delta_time_waited) /
  12.   7               decode(sum(delta_total_waits), 0, null, sum(delta_total_waits)) / 1000,
  13.   8               3) avg_time_ms
  14.   9    from (select hse.instance_number,
  15. 10                 hse.snap_id,
  16. 11                 trunc(sysdate - 30 + 1) +
  17. 12                 trunc((cast(hs.begin_interval_time as date) -
  18. 13                       (trunc(sysdate - 10 + 1))) * 24 /
  19. 14                       (1)) * (1) / 24 time,
  20. 15                 EVENT_NAME,
  21. 16                 (lead(TOTAL_WAITS, 1)
  22. 17                  over(partition by hse.instance_number,
  23. 18                       hs.STARTUP_TIME,
  24. 19                       EVENT_NAME order by hse.snap_id)) - TOTAL_WAITS delta_total_waits,
  25. 20                 (lead(TIME_WAITED_MICRO, 1)
  26. 21                  over(partition by hse.instance_number,
  27. 22                       hs.STARTUP_TIME,
  28. 23                       EVENT_NAME order by hse.snap_id)) - TIME_WAITED_MICRO delta_time_waited
  29. 24            from DBA_HIST_SYSTEM_EVENT hse, DBA_HIST_SNAPSHOT hs
  30. 25           where hse.snap_id = hs.snap_id
  31. 26             and hs.begin_interval_time >= trunc(sysdate) - 30 + 1
  32. 27             and hse.EVENT_NAME in ('db file sequential read','db file scattered read')) a
  33. 28   group by instance_number, time, event_name
  34. 29   order by 1, 2, 3;
  35.       INST TIME                EVENT_NAME                         TOTAL_WAITS   TOTAL_TIME_S    AVG_TIME_MS
  36. ---------- ------------------- ------------------------------ --------------- -------------- --------------
  37.          1 2016-01-21 22:00:00 db file scattered read                  116532       8003.375         68.680
  38.            2016-01-21 22:00:00 db file sequential read                 451345       2617.070          5.798
  39.            2016-01-21 23:00:00 db file scattered read                  509375      60848.652        119.457
  40.            2016-01-21 23:00:00 db file sequential read                1032694       9415.338          9.117
  41.            2016-01-22 00:00:00 db file scattered read                  511267      55300.596        108.164
  42.            2016-01-22 00:00:00 db file sequential read                 665804       5953.620          8.942
  43.            2016-01-22 01:00:00 db file scattered read                  212010      13539.024         63.860
  44.            2016-01-22 01:00:00 db file sequential read                 368793       3063.742          8.307
  45.            2016-01-22 02:00:00 db file scattered read                  161036      19300.935        119.855
  46.            2016-01-22 02:00:00 db file sequential read                 144915       1313.259          9.062
  47.            2016-01-22 03:00:00 db file scattered read                  646679      84395.856        130.507
  48.            2016-01-22 03:00:00 db file sequential read                 335820       3152.971          9.389
  49.            2016-01-22 04:00:00 db file scattered read                  617742      67478.919        109.235
  50.            2016-01-22 04:00:00 db file sequential read                 288044       2563.102          8.898
  51.            2016-01-22 05:00:00 db file scattered read                  493513      59254.417        120.067
  52.            2016-01-22 05:00:00 db file sequential read                 991351       9743.101          9.828
  53.            2016-01-22 06:00:00 db file scattered read                  467135      47366.993        101.399
  54.            2016-01-22 06:00:00 db file sequential read                1511804      13600.312          8.996
  55.            2016-01-22 07:00:00 db file scattered read                  305532      32673.273        106.939
  56.            2016-01-22 07:00:00 db file sequential read                1451034      13513.703          9.313
  57.            2016-01-22 08:00:00 db file scattered read                  469331      33309.734         70.973
  58.            2016-01-22 08:00:00 db file sequential read                1586451      12038.511          7.588
  59.            2016-01-22 09:00:00 db file scattered read                  409206      26532.131         64.838
  60.            2016-01-22 09:00:00 db file sequential read                1876402      11685.365          6.228
  61.            2016-01-22 10:00:00 db file scattered read                  218379      15000.749         68.691
  62.            2016-01-22 10:00:00 db file sequential read                1012738       7195.984          7.105
  63.            2016-01-22 11:00:00 db file scattered read                  280045      27214.605         97.179
  64.            2016-01-22 11:00:00 db file sequential read                 775662       5751.906          7.415
  65.            2016-01-22 12:00:00 db file scattered read                  271739      21270.681         78.276
  66.            2016-01-22 12:00:00 db file sequential read                1013600       6862.144          6.770
  67.            2016-01-22 13:00:00 db file scattered read                   91427       8502.492         92.998
  68.            2016-01-22 13:00:00 db file sequential read                 994440       6992.188          7.031
  69.            2016-01-22 14:00:00 db file scattered read                  143148       6822.649         47.662
  70.            2016-01-22 14:00:00 db file sequential read                 897827       4978.166          5.545
  71.            2016-01-22 15:00:00 db file scattered read                   80698       4790.735         59.366
  72.            2016-01-22 15:00:00 db file sequential read                 507671       2940.978          5.793
  73.            
  74. .................
复制代码
2.2 手动采集多块读与物理读

以为是AWR收集的数据不准确,所以下面自己写个脚本来收集
--1,创建表
  1. drop table system.htz_system_event ;
  2. drop sequence system.htz_system_event_seq;
  3. create sequence system.htz_system_event_seq;
  4. create table system.htz_system_event(start_time date,id number,name varchar2(64),TOTAL_WAITS number,TOTAL_TIMEOUTS number,TIME_WAITED number,AVERAGE_WAIT number,TIME_WAITED_MICRO number,TOTAL_WAITS_FG number,TOTAL_TIMEOUTS_FG number,TIME_WAITED_FG number,AVERAGE_WAIT_FG number,TIME_WAITED_MICRO_FG number) tablespace ODS_MODEL_SETT;
复制代码
--2,自动作业插入数据,每10分钟插入一次
  1. BEGIN
  2.    DBMS_JOB.SUBMIT (
  3.       :jobno,
  4.       'DECLARE
  5.       v_sequence   NUMBER;
  6.       BEGIN
  7.           SELECT system.htz_system_event_seq.nextval INTO v_sequence FROM DUAL;
  8.           insert into system.htz_system_event select sysdate,v_sequence,event,TOTAL_WAITS,TOTAL_TIMEOUTS,TIME_WAITED,AVERAGE_WAIT,TIME_WAITED_MICRO,TOTAL_WAITS_FG,TOTAL_TIMEOUTS_FG,TIME_WAITED_FG,AVERAGE_WAIT_FG,TIME_WAITED_MICRO_FG from v$system_event where wait_class in (''User I/O'',''System I/O'');
  9.       END;',
  10.       SYSDATE,
  11.       'SYSDATE + 10/1440');
  12.    COMMIT;
  13. END;
  14. /
  15. PL/SQL procedure successfully completed.
  16. PRINT jobno
  17. SQL> PRINT jobno
  18.                JOBNO
  19. --------------------
  20.                  703
  21. SQL> set echo off
  22. SQL> set lines 200 pages 3000 heading on
  23. SQL> col name for a30
  24. SQL> col start_time for a11
  25. SQL> col TOTAL_WAITS for 9999999999
  26. SQL> col lag_total_waits for 9999999999
  27. SQL> col TIME_WAITED_MICRO for 9999999999
  28. SQL> col lag_TIME_WAITED_MICRO for 9999999999
  29. SQL> col id for 999999
  30. SQL> col AVERAGE_WAIT for 9999.99
  31. SQL> col AVG_WAIT for 9999.99
  32. SQL>   SELECT TO_CHAR (start_time, 'dd hh24:mi:ss') start_time,
  33.   2           id,
  34.   3           NAME,
  35.   4           TRUNC (a.TOTAL_WAITS / 10000) TOTAL_WAITS,
  36.   5           TRUNC (LAG (total_waits) OVER (PARTITION BY NAME ORDER BY id) / 1000)
  37.   6              lag_total_waits,
  38.   7           TRUNC (a.TIME_WAITED_MICRO / 1000000) TIME_WAITED_MICRO,
  39.   8           TRUNC (
  40.   9                LAG (TIME_WAITED_MICRO) OVER (PARTITION BY name ORDER BY id)
  41. 10              / 1000000)
  42. 11              lag_TIME_WAITED_MICRO,
  43. 12           a.AVERAGE_WAIT,
  44. 13           ROUND (
  45. 14              DECODE (
  46. 15                   total_waits
  47. 16                 - LAG (total_waits) OVER (PARTITION BY NAME ORDER BY id),
  48. 17                 0, NULL,
  49. 18                 (  (  TIME_WAITED_MICRO
  50. 19                     - LAG (TIME_WAITED_MICRO)
  51. 20                          OVER (PARTITION BY name ORDER BY id))
  52. 21                  / (  total_waits
  53. 22                     - LAG (total_waits) OVER (PARTITION BY NAME ORDER BY id))
  54. 23                  / 1000)),
  55. 24              2)
  56. 25              avg_wait
  57. 26      FROM SYSTEM.htz_system_event a
  58. 27     WHERE name IN ('db file scattered read')
  59. 28  ORDER BY name, start_time
  60. 29  /
  61. START_TIME       ID NAME                           TOTAL_WAITS LAG_TOTAL_WAITS TIME_WAITED_MICRO LAG_TIME_WAITED_MICRO AVERAGE_WAIT AVG_WAIT
  62. ----------- ------- ------------------------------ ----------- --------------- ----------------- --------------------- ------------ --------
  63. 19 11:18:55       1 db file scattered read              160921                         124946964                               7.76
  64. 19 11:28:56       2 db file scattered read              160925         1609219         124950029             124946964         7.76    93.00
  65. 19 11:38:57       3 db file scattered read              160927         1609252         124952805             124950029         7.76   107.95
  66. 19 11:48:59       4 db file scattered read              160932         1609278         124955488             124952805         7.76    53.90
  67. 19 11:59:00       5 db file scattered read              160935         1609328         124957105             124955488         7.76    60.11
  68. 19 12:09:02       6 db file scattered read              160939         1609355         124961852             124957105         7.76   108.29
  69. 19 12:19:04       7 db file scattered read              160945         1609398         124968591             124961852         7.76   127.37
  70. 19 12:29:05       8 db file scattered read              160949         1609451         124974549             124968591         7.76   124.38
  71. 19 12:39:07       9 db file scattered read              160953         1609499         124979139             124974549         7.76   131.63
  72. 19 12:49:08      10 db file scattered read              160957         1609534         124983884             124979139         7.77   125.27
  73. 19 12:59:10      11 db file scattered read              160959         1609572         124986769             124983884         7.77   116.43
  74. 19 13:09:12      12 db file scattered read              160969         1609597         124995455             124986769         7.77    90.32
  75. 19 13:19:13      13 db file scattered read              160974         1609693         125001595             124995455         7.77   115.52
  76. 19 13:29:14      14 db file scattered read              160980         1609746         125008342             125001595         7.77   115.31
  77. 19 13:39:16      15 db file scattered read              160984         1609805         125012003             125008342         7.77    92.16
  78. 19 13:49:17      16 db file scattered read              160988         1609844         125016167             125012003         7.77   105.47
  79. 19 13:59:18      17 db file scattered read              160990         1609884         125018127             125016167         7.77    96.30
  80. 19 14:09:20      18 db file scattered read              160994         1609904         125023065             125018127         7.77   109.13
  81. 19 14:19:21      19 db file scattered read              160997         1609949         125025060             125023065         7.77    80.29
  82. 19 14:29:23      20 db file scattered read              161003         1609974         125028340             125025060         7.77    58.06
  83. 19 14:39:24      21 db file scattered read              161008         1610031         125030265             125028340         7.77    37.58
  84. 19 14:49:25      22 db file scattered read              161008         1610082         125030809             125030265         7.77    89.22
  85. 19 14:59:27      23 db file scattered read              161009         1610088         125031182             125030809         7.77    86.79
复制代码
这里手动收集出来跟AWR报告差不多.
2.3 查询文件的碎片

环境中使用的VXFS,所以我们查询一下文件的碎片
  1.                     Volume  Extent Type     File Offset     Extent Size     File
  2.                 vol_data12         Data         0 Bytes        16.00 KB     /data12/oradata/dblv32g_0225.dbf
  3.                 vol_data12         Data        16.00 KB       128.00 KB     /data12/oradata/dblv32g_0225.dbf
  4.                 vol_data12         Data       144.00 KB        32.00 KB     /data12/oradata/dblv32g_0225.dbf
  5.                 vol_data12         Data       176.00 KB        32.00 KB     /data12/oradata/dblv32g_0225.dbf
  6.                 vol_data12         Data       208.00 KB        32.00 KB     /data12/oradata/dblv32g_0225.dbf
  7.                 vol_data12         Data       240.00 KB        32.00 KB     /data12/oradata/dblv32g_0225.dbf
  8.                 vol_data12         Data       272.00 KB        32.00 KB     /data12/oradata/dblv32g_0225.dbf
  9.                 vol_data12         Data       304.00 KB        32.00 KB     /data12/oradata/dblv32g_0225.dbf
  10.                 vol_data12         Data       336.00 KB        32.00 KB     /data12/oradata/dblv32g_0225.dbf
  11.                 vol_data12         Data       368.00 KB        24.00 KB     /data12/oradata/dblv32g_0225.dbf
  12.                 vol_data12         Data       392.00 KB        32.00 KB     /data12/oradata/dblv32g_0225.dbf
  13.                 vol_data12         Data       424.00 KB        32.00 KB     /data12/oradata/dblv32g_0225.dbf
  14.                 vol_data12         Data       456.00 KB        32.00 KB     /data12/oradata/dblv32g_0225.dbf
  15.                 vol_data12         Data       488.00 KB        32.00 KB     /data12/oradata/dblv32g_0225.dbf
  16.                 vol_data12         Data       520.00 KB       128.00 KB     /data12/oradata/dblv32g_0225.dbf
  17.                 vol_data12         Data       648.00 KB       128.00 KB     /data12/oradata/dblv32g_0225.dbf
  18.                 ............
复制代码
这里看到文件系统上面每个区的大小都是32KB,文件存在碎片,并且很严重。在VXFS里面文件的空间分配其实跟ORACLE一样的,连续的块构成区,但是区于区之间有可能不连续的。ORACLE一次IO最大是1M,如果一次多块读1M,需要读32个VXFS里面的区,那么一次ORACLE的IO在VXFS里面间接的变成了32次IO。
2.4 手动创建表空间,查看数据文件的碎片
  1.   下面手动创建一个10G的数据文件,看看文件的碎片如何。
复制代码
  1. SQL> create tablespace htz_test datafile '/data14/oradata/htz_test01.dbf' size 10G autoextend off;
  2. Tablespace created.
  3. [htz.pw:oracle]/oracle/app/oracle/admin/htz/htz>/opt/VRTS/bin/fsmap -aH /data14/oradata/htz_test01.dbf
  4.                     Volume  Extent Type     File Offset     Extent Size     File
  5.                 vol_data14         Data         0 Bytes        10.00 GB     /data14/oradata/htz_test01.dbf
  6. [htz.pw:oracle]/oracle/app/oracle/admin/htz/htz>ls -l  /data14/oradata/htz_test01.dbf
  7. -rw-r-----    1 oracle   dba      10737426432 Feb 19 14:36 /data14/oradata/htz_test01.dbf
复制代码
  1. 可以发现10G的数据文件,只生成了一个区,跟我们之前的数据文件相差很大。
复制代码
2.5 创建表用于测试IO
  1. SQL> create table system.htz_test_table nologging tablespace htz_test  parallel 5 as select /*+ parallel(a 5)*/* from HTZ.HTZHTZHTZ a where rownum <1000000;
  2. SQL> create table system.htz_test_table1 tablespace ODS_MODEL as select * from system.htz_test_table;
复制代码
2.5.1 通过TRUSS,10046来对上面2张表进行分析

旧表空间的表
  1. SQL> alter session set "_serial_direct_read"='NEVER';
  2. Session altered.
  3. Elapsed: 00:00:00.00
  4. SQL> @trace_10046_my.sql
  5. Statement processed.
  6. Statement processed.
  7. /oracle/app/oracle/diag/rdbms/puods/puhtz.pw/trace/puhtz.pw_ora_63111800.trc
  8. 'oradebug event 10046 trace name context off'
  9. select count(*) from system.htz_test_table1;
  10. truss -Ddfo /expdata/63111800.log -p 63111800
  11. SQL> select count(*) from system.htz_test_table1;
  12.   COUNT(*)
  13. ----------
  14.   63999936
  15. Elapsed: 00:11:18.68
复制代码
这里看到SQL执行SQL是11分钟
  1. SQL> select * from v$session_event where sid in (select sid from v$mystat) ;
  2.        SID EVENT                                    TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT   MAX_WAIT TIME_WAITED_MICRO   EVENT_ID WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
  3. ---------- ---------------------------------------- ----------- -------------- ----------- ------------ ---------- ----------------- ---------- ------------- ----------- --------------------
  4.       1659 Disk file operations I/O                         528              0           1            0          0              7621  166678035    1740759767           8 User I/O
  5.       1659 log file sync                                      1              0           0          .06          0               596 1328744198    3386400367           5 Commit
  6.       1659 db file sequential read                            4              0           3          .66          1             26371 2652584166    1740759767           8 User I/O
  7.       1659 db file scattered read                          4543              0       65910        14.51         51         659102331  506183215    1740759767           8 User I/O
  8.       1659 SQL*Net message to client                         18              0           0            0          0                98 2067390145    2000153315           7 Network
  9.       1659 SQL*Net message from client                       17              0       24352       1432.5       7812         243524787 1421975091    2723168908           6 Idle
  10.       1659 events in waitclass Other                          7              0           0          .05          0              3262 1736664284    1893977003           0 Other
  11. 7 rows selected.
复制代码
平均的多块读的时间是14.51   ,单块读的时间是0.66
新表空间的表
  1. truss -Ddfo /expdata/45089246.log -p 45089246
  2. SQL> @myspid
  3. SPID
  4. ------------------------
  5. 45089246
  6. SQL> @mysid.sql
  7. USERENV('SID')
  8. --------------
  9.           1659
  10. SQL> alter session set "_serial_direct_read"='NEVER';
  11. Session altered.
  12. SQL> set lines 200                                                            
  13. SQL> col wait_class for a20                                                   
  14. SQL> col event for a40                                                         
  15. SQL> select * from v$session_event where sid in (select sid from v$mystat) ;   
  16.                                                                           
  17.        SID EVENT                                    TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT   MAX_WAIT TIME_WAITED_MICRO   EVENT_ID WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
  18. ---------- ---------------------------------------- ----------- -------------- ----------- ------------ ---------- ----------------- ---------- ------------- ----------- --------------------
  19.       1659 Disk file operations I/O                           1              0           0            0          0                12  166678035    1740759767           8 User I/O
  20.       1659 log file sync                                      1              0           0           .1          0              1031 1328744198    3386400367           5 Commit
  21.       1659 SQL*Net message to client                         11              0           0            0          0                24 2067390145    2000153315           7 Network
  22.       1659 SQL*Net message from client                       10              0        2594       259.36        935          25935800 1421975091    2723168908           6 Idle
  23. SQL> SQL> set timing on
  24. SQL> @trace_10046_my.sql
  25. Statement processed.
  26. Statement processed.
  27. /oracle/app/oracle/diag/rdbms/puods/puhtz.pw/trace/puhtz.pw_ora_45089246.trc
  28. 'oradebug event 10046 trace name context off'
  29. SQL> select count(*) from system.htz_test_table;
  30.   COUNT(*)
  31. ----------
  32.   63999936
  33. Elapsed: 00:00:37.47
复制代码
这里看到时间是0.37S
  1.        SID EVENT                                    TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT   MAX_WAIT TIME_WAITED_MICRO   EVENT_ID WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
  2. ---------- ---------------------------------------- ----------- -------------- ----------- ------------ ---------- ----------------- ---------- ------------- ----------- --------------------
  3.       1659 Disk file operations I/O                           4              0           0            0          0                69  166678035    1740759767           8 User I/O
  4.       1659 log file sync                                      1              0           0           .1          0              1031 1328744198    3386400367           5 Commit
  5.       1659 db file sequential read                            9              0           5          .57          1             51512 2652584166    1740759767           8 User I/O
  6.       1659 db file scattered read                          4540              0        1696          .37         34          16957162  506183215    1740759767           8 User I/O
  7.       1659 db file parallel read                              5              0          19         3.78          5            188920  834992820    1740759767           8 User I/O
  8.       1659 SQL*Net message to client                         18              0           0            0          0                69 2067390145    2000153315           7 Network
  9.       1659 SQL*Net message from client                       17              0       13426       789.77       5328         134261271 1421975091    2723168908           6 Idle
  10. 7 rows selected.
  11. Elapsed: 00:00:03.51
复制代码
多块读的平均时间是0.37,单块读是0.57
2.5.2 TRUSS文件分析

这里没有贴出详细的内容,只给了有问题的函数
  1. D:\temp>cat 45089246.log|grep lseek|awk  "{print $3}"|awk -F : "{sum+=$1} END {print sum}"
  2. 13.9234
  3. D:\temp>cat 63111800.log|grep lseek|awk  "{print $3}"|awk -F : "{sum+=$1} END {print sum}"
  4. 531.661
  5. D:\temp>cat 63111800.log|grep lseek|wc -l
  6. 5044
  7. D:\temp>cat 45089246.log|grep lseek|wc -l
  8. 3332
复制代码
通过TRUSS文件,可以看到整个函数中,主要是由于LSEEK函数消耗的时间差异很大,才导致整个SQL运行很慢。
2.5.3 通过10046时间分析

新表空间的10046统计信息
旧表空间的10046统计信息
3 分析总结

由于9i使用DG方式升级到11G,在9I中还没有odm,所有在还原数据文件到vxfs时,vxfs会尽量将文件分散,这就导致后来的区不连续,多块读很慢。
4,解决方案

解决方案很简单,其实可以通过sf自己的工具在线做,但是sf工程师说目前没有成功的案例,不做,所以就只能通过ORACLE数据的方法了,使用rman backup as copy将数据文件从一个目录copy到另外一个目录,通过调用odm功能向vxfs里面写数据就可以了。
------------------作者介绍-----------------------
姓名:黄廷忠
现就职:Oracle中国高级服务团队
曾就职:OceanBase、云和恩墨、东方龙马等
电话、微信、QQ:18081072613
个人博客: (http://www.htz.pw)
CSDN地址: (https://blog.csdn.net/wwwhtzpw)
博客园地址: (https://www.cnblogs.com/www-htz-pw)
1.png


来源:程序园用户自行投稿发布,如果侵权,请联系站长删除
免责声明:如果侵犯了您的权益,请联系站长,我们会及时删除侵权内容,谢谢合作!
您需要登录后才可以回帖 登录 | 立即注册