Skip to content

MDATA恢复场景1：在数据库不能打开，SYSTEM表空间还完整的时候

版本v1.2
该功能点使用介绍：

  • 列出用户: list user
  • 列出用户下的所有表: list table username
  • 恢复表: unload table username.tablename
  • 也可以按用户恢复： unload user username

具体操作如下：

MDATA>list table luda
OWNER                         TABLE
---------------               --------------
LUDA                          T1
MDATA>list view luda
OWNER                         VIEW
---------------               --------------
LUDA                          V$T1
MDATA>list index luda
OWNER                         INDEX
---------------               --------------
LUDA                          IDX_ID_T1
MDATA>unload dict
MDATA>list table luda
OWNER                         TABLE
---------------               --------------
LUDA                          T1

MDATA>help

help      ----   get command list
exit      ----   exit from minidul
unload    ----   unload data
  unload table <schema .tablename>    ----   unload data
  unload table all
  unload user </schema><schema name>
list      ----   list schema object,partition,datafile
  list user
  list <table | view | procedure | function | index | package | sequence> <user_ name>

MDATA>unload table luda.t1
schema:LUDA;tab:T1
tabName:LUDA.T1,dic_obj:com.olm.dic.Dict@79e2bf04,getFileid:4,getBlockid:59

导出的数据放置在MDATA目录下的data文件夹中，在该例子中生成了表luda.t1的LUDA.T1.ctl（sqlload 控制文件）以及LUDA.T1.DAT（实际的文本格式数据）

导入方法：
切换到data目录，执行如下命令
sqlldr userid=test/test@luda control=C:\Users\ludatou\Desktop\MDATA01\data\LUDA.T1.ctl

将该表数据导入到test用户中.如果以用户的方式导出，则导入整个用户数据到test用户.

MDATA | Guang Cai Li |

浅谈log buffer space等待事件

什么是log buffer space？

该等待事件问进程等待log buffer空间，因为此时写入log buffer的redo entry速度要高于lgwr 将redo entry写入online redolog的速度，导致log buffer塞满进而产生log buffer space等待事件。深入一点解释就是在往log buffer写入redo entry时候要先获取redo allocation latch，在获取该latch后开始寻获log buffer中剩余的空闲区域写入数据，如果此时没有剩余空间给与写入redo entry则发生log buffer space等待事件，此时可能也会等待log file switch completion事件，因为如果此时遭遇redo online log写满的情况则会发生log switch的情况，在切换过程 logbuffer瞬间写满日志，lgwr进程等待切换结束则出现switch相关等待事件，同时在切换完成后由于大量进程瞬间往log buffer space写入redo entry导致buffer塞满则此时等待log buffer space事件。

应该搜集那些信息来分析’log buffer space’等待事件？

1.发生此事件时候的日志切换频率
2.实例的内存设置以及AWR或者statspack报告
3.发生此事件时候实例的日志切换频率
4.发生此事件时候系统的整体IO负载
5.如果为Dataguard环境，检查DG的模式以及日志传输的延时情况

触发’log buffer space’等待事件的原因？

1.系统IO能力不足
2.日志切换过于频繁
3.过小的log buffer
4.Dataguard在最大可用模式以上保护级别的络传输效率低下

如何处理log buffer space等待事件？

导致log buffer space的原因前面分析过了，针对前面的情况大致的列出一些处理思路。
1.系统IO能力不足这个在log file sync的讨论中介绍过了该如何处理，尽量提升io能力，将redo log放在io能力高的存储上
2.日志切换过于频繁这个时候一般都会导致log buffer space和log file switch completion的等待，如果日志小了，频繁的切换会导致此2个事件的产生，所以一般建议将redo设置大一些，并放在io能力高的文件系统
3.过小的log buffer，这个情况和2有相似点，可能同时存在redo logfile size过小，log bufer过小的情况，再此时如果把log buffer设置大点log file sync等待就可能增加，所以针对不同的log buffer大小对log buffer space事件的影响做个测试验证下。

测试：

1.构建T1表10w条记录
2.在log buffer 256k时候update t1表
3.在log buffer 10m时候update t1表
然后分别确认2和3的log buffer space等待情况

1.构建T1表

SQL> select count(*) from t1;

  COUNT(*)
----------
     150068

SQL> insert into t1 select * from t1;

150068 rows created.

SQL> commit;

Commit complete.

SQL> select count(*) from t1;

  COUNT(*)
----------
    300136

SQL> alter table t1 add num number;

Table altered.

SQL> alter table t1 modify num varchar2(200);

Table altered.

SQL> select num from t1 where rownum < 2;

NUM
--------------------------------------------------------------------------------
AAAMr8AAEAAAAA8AAA

2.在log buffer 2M时候update t1表

在表t1中更新30w条数据，同时观察等待
SQL> show sga

Total System Global Area  318767104 bytes
Fixed Size                  1267260 bytes
Variable Size             100665796 bytes
Database Buffers          213909504 bytes
Redo Buffers                2924544 bytes
SQL> conn luda/luda
Connected.
SQL> @sess_stat
SP2-0158: unknown SET option "header"

EVENT                                                            TOTAL_WAITS TIME_WAITED
---------------------------------------------------------------- ----------- -----------
SQL*Net message from client                                               11        4439
db file sequential read                                                   55           0
SQL*Net message to client                                                 12           0

SQL> update t1 set object_name='LUDATOU',num=rowid;

300408 rows updated.

SQL> @sess_stat
SP2-0158: unknown SET option "header"

EVENT                                                            TOTAL_WAITS TIME_WAITED
---------------------------------------------------------------- ----------- -----------
SQL*Net message from client                                               14        8837
log buffer space                                                          11          37
log file switch completion                                                 8           7
db file scattered read                                                   544           6
events in waitclass Other                                                 31           1
SQL*Net message to client                                                 15           0
db file sequential read                                                   70           0
观察整体的等待

SQL> @snaper all,out 5 3 214

-- Session Snapper v2.02 by Tanel Poder ( http://www.tanelpoder.com )

----------------------------------------------------------------------------------------------------------------------
    SID, USERNAME  , TYPE, STATISTIC                               ,         DELTA, HDELTA/SEC,    %TIME, GRAPH
----------------------------------------------------------------------------------------------------------------------
    214, LUDA      , STAT, opened cursors cumulative               ,           198,       39.6,
    214, LUDA      , STAT, user calls                              ,             2,         .4,
    214, LUDA      , STAT, recursive calls                         ,          2007,      401.4,
    214, LUDA      , STAT, recursive cpu usage                     ,            12,        2.4,
    214, LUDA      , STAT, session logical reads                   ,        390254,     78.05k,
    214, LUDA      , STAT, CPU used by this session                ,           198,       39.6,
    214, LUDA      , STAT, DB time                                 ,           261,       52.2,
    214, LUDA      , STAT, user I/O wait time                      ,             6,        1.2,
    214, LUDA      , STAT, session uga memory                      ,         65464,     13.09k,
    214, LUDA      , STAT, session uga memory max                  ,         65464,     13.09k,
    214, LUDA      , STAT, messages sent                           ,           365,         73,
    214, LUDA      , STAT, session pga memory                      ,         65536,     13.11k,
    214, LUDA      , STAT, session pga memory max                  ,         65536,     13.11k,
    214, LUDA      , STAT, enqueue requests                        ,           836,      167.2,
    214, LUDA      , STAT, enqueue conversions                     ,           113,       22.6,
    214, LUDA      , STAT, enqueue releases                        ,           834,      166.8,
    214, LUDA      , STAT, physical read total IO requests         ,           559,      111.8,
    214, LUDA      , STAT, physical read total multi block requests,           544,      108.8,
    214, LUDA      , STAT, physical read total bytes               ,      35151872,      7.03M,
    214, LUDA      , STAT, db block gets                           ,        383374,     76.67k,
    214, LUDA      , STAT, db block gets from cache                ,        383374,     76.67k,
    214, LUDA      , STAT, consistent gets                         ,          6880,      1.38k,
    214, LUDA      , STAT, consistent gets from cache              ,          6880,      1.38k,
    214, LUDA      , STAT, consistent gets - examination           ,          1695,        339,
    214, LUDA      , STAT, physical reads                          ,          4291,      858.2,
    214, LUDA      , STAT, physical reads cache                    ,          4291,      858.2,
    214, LUDA      , STAT, physical read IO requests               ,           559,      111.8,
    214, LUDA      , STAT, physical read bytes                     ,      35151872,      7.03M,
    214, LUDA      , STAT, db block changes                        ,        655501,     131.1k,
    214, LUDA      , STAT, change write time                       ,           105,         21,
    214, LUDA      , STAT, redo synch writes                       ,             1,         .2,
    214, LUDA      , STAT, free buffer requested                   ,         13313,      2.66k,
    214, LUDA      , STAT, switch current to new buffer            ,          4241,      848.2,
    214, LUDA      , STAT, write clones created in foreground      ,             3,         .6,
    214, LUDA      , STAT, physical reads cache prefetch           ,          3732,      746.4,
    214, LUDA      , STAT, shared hash latch upgrades - no wait    ,             5,          1,
    214, LUDA      , STAT, calls to kcmgcs                         ,           132,       26.4,
    214, LUDA      , STAT, calls to kcmgas                         ,          9027,      1.81k,
    214, LUDA      , STAT, calls to get snapshot scn: kcmgss       ,           786,      157.2,
    214, LUDA      , STAT, redo entries                            ,        326611,     65.32k,
    214, LUDA      , STAT, redo size                               ,      96942748,     19.39M,
    214, LUDA      , STAT, redo buffer allocation retries          ,            15,          3,
    214, LUDA      , STAT, redo log space requests                 ,             8,        1.6,
    214, LUDA      , STAT, redo log space wait time                ,             7,        1.4,
    214, LUDA      , STAT, redo ordering marks                     ,          4744,      948.8,
    214, LUDA      , STAT, redo subscn max counts                  ,          6443,      1.29k,
    214, LUDA      , STAT, undo change vector size                 ,      37734184,      7.55M,
    214, LUDA      , STAT, no work - consistent read gets          ,          2974,      594.8,
    214, LUDA      , STAT, cleanouts only - consistent read gets   ,          1661,      332.2,
    214, LUDA      , STAT, immediate (CR) block cleanout applicatio,          1661,      332.2,
    214, LUDA      , STAT, deferred (CURRENT) block cleanout applic,          2582,      516.4,
    214, LUDA      , STAT, commit txn count during cleanout        ,          1661,      332.2,
    214, LUDA      , STAT, cleanout - number of ktugct calls       ,          1661,      332.2,
    214, LUDA      , STAT, IMU Flushes                             ,             1,         .2,
    214, LUDA      , STAT, table scans (short tables)              ,           173,       34.6,
    214, LUDA      , STAT, table scans (long tables)               ,             1,         .2,
    214, LUDA      , STAT, table scan rows gotten                  ,        325791,     65.16k,
    214, LUDA      , STAT, table scan blocks gotten                ,          4607,      921.4,
    214, LUDA      , STAT, table fetch by rowid                    ,             9,        1.8,
    214, LUDA      , STAT, cluster key scans                       ,             8,        1.6,
    214, LUDA      , STAT, cluster key scan block gets             ,             8,        1.6,
    214, LUDA      , STAT, rows fetched via callback               ,             1,         .2,
    214, LUDA      , STAT, index crx upgrade (positioned)          ,             2,         .4,
    214, LUDA      , STAT, index fetch by key                      ,            11,        2.2,
    214, LUDA      , STAT, index scans kdiixs1                     ,            14,        2.8,
    214, LUDA      , STAT, session cursor cache hits               ,           177,       35.4,
    214, LUDA      , STAT, session cursor cache count              ,             1,         .2,
    214, LUDA      , STAT, cursor authentications                  ,             2,         .4,
    214, LUDA      , STAT, buffer is pinned count                  ,        296391,     59.28k,
    214, LUDA      , STAT, buffer is not pinned count              ,            26,        5.2,
    214, LUDA      , STAT, workarea executions - optimal           ,             5,          1,
    214, LUDA      , STAT, parse time cpu                          ,             1,         .2,
    214, LUDA      , STAT, parse time elapsed                      ,             1,         .2,
    214, LUDA      , STAT, parse count (total)                     ,           188,       37.6,
    214, LUDA      , STAT, parse count (hard)                      ,             6,        1.2,
    214, LUDA      , STAT, execute count                           ,           198,       39.6,
    214, LUDA      , STAT, bytes sent via SQL*Net to client        ,           147,       29.4,
    214, LUDA      , STAT, bytes received via SQL*Net from client  ,           208,       41.6,
    214, LUDA      , STAT, SQL*Net roundtrips to/from client       ,             1,         .2,
    214, LUDA      , STAT, sorts (memory)                          ,             9,        1.8,
    214, LUDA      , STAT, sorts (rows)                            ,            33,        6.6,
    214, LUDA      , TIME, hard parse elapsed time                 ,          7721,     1.54ms,      .2%, |          |
    214, LUDA      , TIME, repeated bind elapsed time              ,            23,      4.6us,      .0%, |          |
    214, LUDA      , TIME, parse time elapsed                      ,         17186,     3.44ms,      .3%, |          |
    214, LUDA      , TIME, DB CPU                                  ,       1980114,   396.02ms,    39.6%, |@@@@      |
    214, LUDA      , TIME, sql execute elapsed time                ,       2544856,   508.97ms,    50.9%, |@@@@@@    |
    214, LUDA      , TIME, DB time                                 ,       2547798,   509.56ms,    51.0%, |@@@@@@    |
    214, LUDA      , WAIT, log buffer space                        ,        373101,    74.62ms,     7.5%, |@         |
    214, LUDA      , WAIT, log file switch completion              ,         73175,    14.64ms,     1.5%, |@         |
    214, LUDA      , WAIT, db file sequential read                 ,          1750,      350us,      .0%, |          |
    214, LUDA      , WAIT, db file scattered read                  ,         59996,       12ms,     1.2%, |@         |
    214, LUDA      , WAIT, SQL*Net message to client               ,             4,       .8us,      .0%, |          |
    214, LUDA      , WAIT, SQL*Net message from client             ,       1448235,   289.65ms,    29.0%, |@@@       |
--  End of snap 1, end=2014-07-16 16:34:54, seconds=5

通过以上测试我们可以发现，在2M左右大小的log buffer中，更新表t1过程总体产生的log buffer space等待为74.62ms，log buffer space等待触发次数11次.
继续第二步测试。

3.在log buffer 10M时候update t1表

SQL> conn luda/luda
Connected.
SQL>  update t1 set object_name='LUDATOU',num=rowid;

300408 rows updated.

SQL> @sess_stat
SP2-0158: unknown SET option "header"

EVENT                                                            TOTAL_WAITS TIME_WAITED
---------------------------------------------------------------- ----------- -----------
SQL*Net message from client                                               12        2951
log file switch (checkpoint incomplete)                                    4         112
log file switch completion                                                 5          45
events in waitclass Other                                                  4          11
db file scattered read                                                   544           5
Data file init write                                                      21           4
log buffer space                                                           2           2
control file parallel write                                                9           1
SQL*Net message to client                                                 13           0
db file parallel read                                                      1           0
db file single write                                                       3           0
control file sequential read                                              60           0
db file sequential read                                                   71           0

13 rows selected.

同时观测总体等待
SQL>  @snaper all,out 5 3 214


-- Session Snapper v2.02 by Tanel Poder ( http://www.tanelpoder.com )

----------------------------------------------------------------------------------------------------------------------
    SID, USERNAME  , TYPE, STATISTIC                               ,         DELTA, HDELTA/SEC,    %TIME, GRAPH
----------------------------------------------------------------------------------------------------------------------
    214, LUDA      , STAT, opened cursors cumulative               ,            80,         16,
    214, LUDA      , STAT, opened cursors current                  ,             1,         .2,
    214, LUDA      , STAT, user calls                              ,             1,         .2,
    214, LUDA      , STAT, recursive calls                         ,           955,        191,
    214, LUDA      , STAT, recursive cpu usage                     ,             9,        1.8,
    214, LUDA      , STAT, session logical reads                   ,        344227,     68.85k,
    214, LUDA      , STAT, CPU used by this session                ,           196,       39.2,
    214, LUDA      , STAT, user I/O wait time                      ,             7,        1.4,
    214, LUDA      , STAT, messages sent                           ,           107,       21.4,
    214, LUDA      , STAT, session pga memory                      ,       4587520,     917.5k,
    214, LUDA      , STAT, session pga memory max                  ,       4587520,     917.5k,
    214, LUDA      , STAT, enqueue waits                           ,             1,         .2,
    214, LUDA      , STAT, enqueue requests                        ,           220,         44,
    214, LUDA      , STAT, enqueue conversions                     ,            26,        5.2,
    214, LUDA      , STAT, enqueue releases                        ,           218,       43.6,
    214, LUDA      , STAT, physical read total IO requests         ,           575,        115,
    214, LUDA      , STAT, physical read total multi block requests,           513,      102.6,
    214, LUDA      , STAT, physical read total bytes               ,      33865728,      6.77M,
    214, LUDA      , STAT, physical write total IO requests        ,            32,        6.4,
    214, LUDA      , STAT, physical write total multi block request,            10,          2,
    214, LUDA      , STAT, physical write total bytes              ,      10797056,      2.16M,
    214, LUDA      , STAT, db block gets                           ,        335817,     67.16k,
    214, LUDA      , STAT, db block gets from cache                ,        335817,     67.16k,
    214, LUDA      , STAT, consistent gets                         ,          8410,      1.68k,
    214, LUDA      , STAT, consistent gets from cache              ,          8410,      1.68k,
    214, LUDA      , STAT, consistent gets - examination           ,          4064,      812.8,
    214, LUDA      , STAT, physical reads                          ,          4050,        810,
    214, LUDA      , STAT, physical reads cache                    ,          4050,        810,
    214, LUDA      , STAT, physical read IO requests               ,           531,      106.2,
    214, LUDA      , STAT, physical read bytes                     ,      33177600,      6.64M,
    214, LUDA      , STAT, db block changes                        ,        611828,    122.37k,
    214, LUDA      , STAT, prefetch clients - default              ,             1,         .2,
    214, LUDA      , STAT, change write time                       ,            49,        9.8,
    214, LUDA      , STAT, free buffer requested                   ,         12576,      2.52k,
    214, LUDA      , STAT, switch current to new buffer            ,          4030,        806,
    214, LUDA      , STAT, physical reads cache prefetch           ,          3522,      704.4,
    214, LUDA      , STAT, shared hash latch upgrades - no wait    ,             3,         .6,
    214, LUDA      , STAT, calls to kcmgcs                         ,             5,          1,
    214, LUDA      , STAT, calls to kcmgas                         ,          8532,      1.71k,
    214, LUDA      , STAT, calls to get snapshot scn: kcmgss       ,           273,       54.6,
    214, LUDA      , STAT, redo entries                            ,        305759,     61.15k,
    214, LUDA      , STAT, redo size                               ,      91112824,     18.22M,
    214, LUDA      , STAT, redo buffer allocation retries          ,             7,        1.4,
    214, LUDA      , STAT, redo log space requests                 ,             6,        1.2,
    214, LUDA      , STAT, redo log space wait time                ,            59,       11.8,
    214, LUDA      , STAT, redo ordering marks                     ,          4489,      897.8,
    214, LUDA      , STAT, redo subscn max counts                  ,          8528,      1.71k,
    214, LUDA      , STAT, undo change vector size                 ,      35556100,      7.11M,
    214, LUDA      , STAT, no work - consistent read gets          ,           133,       26.6,
    214, LUDA      , STAT, cleanouts only - consistent read gets   ,          4030,        806,
    214, LUDA      , STAT, immediate (CR) block cleanout applicatio,          4030,        806,
    214, LUDA      , STAT, commit txn count during cleanout        ,          4030,        806,
    214, LUDA      , STAT, cleanout - number of ktugct calls       ,          4030,        806,
    214, LUDA      , STAT, auto extends on undo tablespace         ,             2,         .4,
    214, LUDA      , STAT, IMU pool not allocated                  ,             1,         .2,
    214, LUDA      , STAT, IMU- failed to get a private strand     ,             1,         .2,
    214, LUDA      , STAT, table scans (short tables)              ,            55,         11,
    214, LUDA      , STAT, table scans (long tables)               ,             1,         .2,
    214, LUDA      , STAT, table scan rows gotten                  ,        313370,     62.67k,
    214, LUDA      , STAT, table scan blocks gotten                ,          4135,        827,
    214, LUDA      , STAT, table fetch by rowid                    ,             9,        1.8,
    214, LUDA      , STAT, cluster key scans                       ,             8,        1.6,
    214, LUDA      , STAT, cluster key scan block gets             ,             8,        1.6,
    214, LUDA      , STAT, rows fetched via callback               ,             1,         .2,
    214, LUDA      , STAT, index crx upgrade (positioned)          ,             2,         .4,
    214, LUDA      , STAT, index fetch by key                      ,            11,        2.2,
    214, LUDA      , STAT, index scans kdiixs1                     ,            14,        2.8,
    214, LUDA      , STAT, session cursor cache hits               ,            59,       11.8,
    214, LUDA      , STAT, cursor authentications                  ,             2,         .4,
    214, LUDA      , STAT, buffer is pinned count                  ,        285420,     57.08k,
    214, LUDA      , STAT, buffer is not pinned count              ,            26,        5.2,
    214, LUDA      , STAT, workarea executions - optimal           ,             5,          1,
    214, LUDA      , STAT, parse time cpu                          ,             1,         .2,
    214, LUDA      , STAT, parse count (total)                     ,            70,         14,
    214, LUDA      , STAT, parse count (hard)                      ,             6,        1.2,
    214, LUDA      , STAT, execute count                           ,            80,         16,
    214, LUDA      , STAT, bytes received via SQL*Net from client  ,           194,       38.8,
    214, LUDA      , STAT, sorts (memory)                          ,             9,        1.8,
    214, LUDA      , STAT, sorts (rows)                            ,            33,        6.6,
    214, LUDA      , TIME, hard parse elapsed time                 ,          7737,     1.55ms,      .2%, |          |
    214, LUDA      , TIME, repeated bind elapsed time              ,            46,      9.2us,      .0%, |          |
    214, LUDA      , TIME, parse time elapsed                      ,         11032,     2.21ms,      .2%, |          |
    214, LUDA      , TIME, DB CPU                                  ,       1620000,      324ms,    32.4%, |@@@@      |
    214, LUDA      , TIME, sql execute elapsed time                ,       2440182,   488.04ms,    48.8%, |@@@@@     |
    214, LUDA      , TIME, DB time                                 ,       2442540,   488.51ms,    48.9%, |@@@@@     |
    214, LUDA      , WAIT, Data file init write                    ,         25778,     5.16ms,      .5%, |@         |
    214, LUDA      , WAIT, control file sequential read            ,           447,     89.4us,      .0%, |          |
    214, LUDA      , WAIT, control file parallel write             ,          6142,     1.23ms,      .1%, |          |
    214, LUDA      , WAIT, log buffer space                        ,         19503,      3.9ms,      .4%, |          |
    214, LUDA      , WAIT, log file switch (checkpoint incomplete) ,        127979,     25.6ms,     2.6%, |@         |
    214, LUDA      , WAIT, log file switch completion              ,        446061,    89.21ms,     8.9%, |@         |
    214, LUDA      , WAIT, db file sequential read                 ,           419,     83.8us,      .0%, |          |
    214, LUDA      , WAIT, db file scattered read                  ,         49967,     9.99ms,     1.0%, |@         |
    214, LUDA      , WAIT, db file single write                    ,           998,    199.6us,      .0%, |          |
    214, LUDA      , WAIT, SQL*Net message from client             ,       2462840,   492.57ms,    49.3%, |@@@@@     |

通过测试3可以发现在10m左右的log buffer 中log buffer space总的等待时间为3.9ms，总体等待次数2次。

测试3和测试2说明了在log buffer加大的情况下，log buffer space等待次数降低，但是log file switch completion等待也随着增加，所以调整log buffer space从整体的等待来看加大log buffer并不是绝对的。
另一种方法来降低log buffer space的办法就是减少redo的产生量，比如nologging或者直接路径写。

4.DG中的日志传输延时影响

在这种情况中可以参考前面的gc block lost中网络的调整，保证日志的传输效率。
还有一种就是压缩日志大小。

Oracle 数据技术 浅谈oracle技术系列 等待事件 | Guang Cai Li | |   log buffer space

浅谈log file sync等待事件诊断（三）

提供一个辅助诊断log file sync的脚本，该脚本有助于诊断log file sync时候锁需要的数据库相关信息的获取，具体如下：

-- NAME: LFSDIAG.SQL
-- ------------------------------------------------------------------------
-- AUTHOR: Michael Polaski - Oracle Support Services
-- ------------------------------------------------------------------------
-- PURPOSE:
-- This script is intended to provide a user friendly guide to troubleshoot
-- log file sync waits. The script will look at important parameters involved
-- in log file sync waits, log file sync wait histogram data, and the script
-- will look at the worst average log file sync times in the active session
-- history data and AWR data and dump information to help determine why those
-- times were the highest. The script will create a file called
-- lfsdiag_<timestamp>.out in your local directory.

set echo off
set feedback off
column timecol new_value timestamp
column spool_extension new_value suffix
select to_char(sysdate,'Mondd_hh24mi') timecol,
'.out' spool_extension from sys.dual;
column output new_value dbname
select value || '_' output
from v$parameter where name = 'db_name';
spool lfsdiag_&&dbname&&timestamp&&suffix
set trim on
set trims on
set lines 140
set pages 100
set verify off
alter session set optimizer_features_enable = '10.2.0.4';

PROMPT LFSDIAG DATA FOR &&dbname&&timestamp
PROMPT Note: All timings are in milliseconds (1000 milliseconds = 1 second)

PROMPT
PROMPT IMPORTANT PARAMETERS RELATING TO LOG FILE SYNC WAITS:
column name format a40 wra
column value format a40 wra
select inst_id, name, value from gv$parameter
where ((value is not null and name like '%log_archive%') or
name like '%commit%' or name like '%event=%' or name like '%lgwr%')
and name not in (select name from gv$parameter where (name like '%log_archive_dest_state%'
and value = 'enable') or name = 'log_archive_format')
order by 1,2,3;

PROMPT
PROMPT ASH THRESHOLD...
PROMPT
PROMPT This will be the threshold in milliseconds for average log file sync
PROMPT times. This will be used for the next queries to look for the worst
PROMPT 'log file sync' minutes. Any minutes that have an average log file
PROMPT sync time greater than the threshold will be analyzed further.
column threshold_in_ms new_value threshold format 999999999.999
select min(threshold_in_ms) threshold_in_ms
from (select inst_id, to_char(sample_time,'Mondd_hh24mi') minute,
avg(time_waited)/1000 threshold_in_ms
from gv$active_session_history
where event = 'log file sync'
group by inst_id,to_char(sample_time,'Mondd_hh24mi')
order by 3 desc)
where rownum <= 10;

PROMPT
PROMPT ASH WORST MINUTES FOR LOG FILE SYNC WAITS:
PROMPT
PROMPT APPROACH: These are the minutes where the avg log file sync time
PROMPT was the highest (in milliseconds).
column minute format a12 tru
column event format a30 tru
column program format a40 tru
column total_wait_time format 999999999999.999
column avg_time_waited format 999999999999.999
select to_char(sample_time,'Mondd_hh24mi') minute, inst_id, event,
sum(time_waited)/1000 TOTAL_WAIT_TIME , count(*) WAITS,
avg(time_waited)/1000 AVG_TIME_WAITED
from gv$active_session_history
where event = 'log file sync'
group by to_char(sample_time,'Mondd_hh24mi'), inst_id, event
having avg(time_waited)/1000 > &&threshold
order by 1,2;

PROMPT
PROMPT ASH LFS BACKGROUND PROCESS WAITS DURING WORST MINUTES:
PROMPT
PROMPT APPROACH: What is LGWR doing when 'log file sync' waits
PROMPT are happening? LMS info may be relevent for broadcast
PROMPT on commit and LNS data may be relevant for dataguard.
PROMPT If more details are needed see the ASH DETAILS FOR WORST
PROMPT MINUTES section at the bottom of the report.
column inst format 999
column minute format a12 tru
column event format a30 tru
column program format a40 wra
select to_char(sample_time,'Mondd_hh24mi') minute, inst_id inst, program, event,
sum(time_waited)/1000 TOTAL_WAIT_TIME , count(*) WAITS,
avg(time_waited)/1000 AVG_TIME_WAITED
from gv$active_session_history
where to_char(sample_time,'Mondd_hh24mi') in (select to_char(sample_time,'Mondd_hh24mi')
from gv$active_session_history
where event = 'log file sync'
group by to_char(sample_time,'Mondd_hh24mi'), inst_id
having avg(time_waited)/1000 > &&threshold and sum(time_waited)/1000 > 1)
and (program like '%LGWR%' or program like '%LMS%' or
program like '%LNS%' or event = 'log file sync')
group by to_char(sample_time,'Mondd_hh24mi'), inst_id, program, event
order by 1,2,3,5 desc, 4;

PROMPT
PROMPT HISTOGRAM DATA FOR LFS AND OTHER RELATED WAITS:
PROMPT
PROMPT APPROACH: Look at the wait distribution for log file sync waits
PROMPT by looking at "wait_time_milli". Look at the high wait times then
PROMPT see if you can correlate those with other related wait events.
column event format a40 wra
select inst_id, event, wait_time_milli, wait_count
from gv$event_histogram
where event in ('log file sync','gcs log flush sync',
'log file parallel write','wait for scn ack',
'log file switch completion','gc cr grant 2-way',
'gc buffer busy','gc current block 2-way') or
event like '%LGWR%' or event like '%LNS%'
order by 2 desc,1,3;

PROMPT
PROMPT ORDERED BY WAIT_TIME_MILLI
select inst_id, event, wait_time_milli, wait_count
from gv$event_histogram
where event in ('log file sync','gcs log flush sync',
'log file parallel write','wait for scn ack',
'log file switch completion','gc cr grant 2-way',
'gc buffer busy','gc current block 2-way')
or event like '%LGWR%' or event like '%LNS%'
order by 3,1,2 desc;

PROMPT
PROMPT REDO WRITE STATS
PROMPT
PROMPT "redo write time" in centiseconds (100 per second)
PROMPT 11.1: "redo write broadcast ack time" in centiseconds (100 per second)
PROMPT 11.2: "redo write broadcast ack time" in microseconds (1000 per millisecond)
column value format 99999999999999999999
column milliseconds format 99999999999999.999
select v.version, ss.inst_id, ss.name, ss.value,
decode(substr(version,1,4),
'11.1',decode (name,'redo write time',value*10,
'redo write broadcast ack time',value*10),
'11.2',decode (name,'redo write time',value*10,
'redo write broadcast ack time',value/1000),
decode (name,'redo write time',value*10)) milliseconds
from gv$sysstat ss, v$instance v
where name like 'redo write%' and value > 0
order by 1,2,3;

PROMPT
PROMPT AWR WORST AVG LOG FILE SYNC SNAPS:
PROMPT
PROMPT APPROACH: These are the AWR snaps where the average 'log file sync'
PROMPT times were the highest.
column begin format a12 tru
column end format a12 tru
column name format a13 tru
select dhs.snap_id, dhs.instance_number inst, to_char(dhs.begin_interval_time,'Mondd_hh24mi') BEGIN,
to_char(dhs.end_interval_time,'Mondd_hh24mi') END,
en.name, se.time_waited_micro/1000 total_wait_time, se.total_waits,
se.time_waited_micro/1000 / se.total_waits avg_time_waited
from dba_hist_snapshot dhs, wrh$_system_event se, v$event_name en
where (dhs.snap_id = se.snap_id and dhs.instance_number = se.instance_number)
and se.event_id = en.event_id and en.name = 'log file sync' and
dhs.snap_id in (select snap_id from (
select se.snap_id, se.time_waited_micro/1000 / se.total_waits avg_time_waited
from wrh$_system_event se, v$event_name en
where se.event_id = en.event_id and en.name = 'log file sync'
order by avg_time_waited desc)
where rownum < 4)
order by 1,2;

PROMPT
PROMPT AWR REDO WRITE STATS
PROMPT
PROMPT "redo write time" in centiseconds (100 per second)
PROMPT 11.1: "redo write broadcast ack time" in centiseconds (100 per second)
PROMPT 11.2: "redo write broadcast ack time" in microseconds (1000 per millisecond)
column stat_name format a30 tru
select v.version, ss.snap_id, ss.instance_number inst, sn.stat_name, ss.value,
decode(substr(version,1,4),
'11.1',decode (stat_name,'redo write time',value*10,
'redo write broadcast ack time',value*10),
'11.2',decode (stat_name,'redo write time',value*10,
'redo write broadcast ack time',value/1000),
decode (stat_name,'redo write time',value*10)) milliseconds
from wrh$_sysstat ss, wrh$_stat_name sn, v$instance v
where ss.stat_id = sn.stat_id
and sn.stat_name like 'redo write%' and ss.value > 0
and ss.snap_id in (select snap_id from (
select se.snap_id, se.time_waited_micro/1000 / se.total_waits avg_time_waited
from wrh$_system_event se, v$event_name en
where se.event_id = en.event_id and en.name = 'log file sync'
order by avg_time_waited desc)
where rownum < 4)
order by 1,2,3;

PROMPT
PROMPT AWR LFS AND OTHER RELATED WAITS FOR WORST LFS AWRs:
PROMPT
PROMPT APPROACH: These are the AWR snaps where the average 'log file sync'
PROMPT times were the highest. Look at related waits at those times.
column name format a40 tru
select se.snap_id, se.instance_number inst, en.name,
se.total_waits, se.time_waited_micro/1000 total_wait_time,
se.time_waited_micro/1000 / se.total_waits avg_time_waited
from wrh$_system_event se, v$event_name en
where se.event_id = en.event_id and (en.name in
('log file sync','gcs log flush sync',
'log file parallel write','wait for scn ack',
'log file switch completion','gc cr grant 2-way',
'gc buffer busy','gc current block 2-way')
or en.name like '%LGWR%' or en.name like '%LNS%')
and se.snap_id in (select snap_id from (
select se.snap_id, se.time_waited_micro/1000 / se.total_waits avg_time_waited
from wrh$_system_event se, v$event_name en
where se.event_id = en.event_id and en.name = 'log file sync'
order by avg_time_waited desc)
where rownum < 4)
order by 1, 6 desc;

PROMPT
PROMPT AWR HISTOGRAM DATA FOR LFS AND OTHER RELATED WAITS FOR WORST LFS AWRs:
PROMPT Note: This query won't work on 10.2 - ORA-942
PROMPT
PROMPT APPROACH: Look at the wait distribution for log file sync waits
PROMPT by looking at "wait_time_milli". Look at the high wait times then
PROMPT see if you can correlate those with other related wait events.
select eh.snap_id, eh.instance_number inst, en.name, eh.wait_time_milli, eh.wait_count
from wrh$_event_histogram eh, v$event_name en
where eh.event_id = en.event_id and
(en.name in ('log file sync','gcs log flush sync',
'log file parallel write','wait for scn ack',
'log file switch completion','gc cr grant 2-way',
'gc buffer busy','gc current block 2-way')
or en.name like '%LGWR%' or en.name like '%LNS%')
and snap_id in (select snap_id from (
select se.snap_id, se.time_waited_micro/1000 / se.total_waits avg_time_waited
from wrh$_system_event se, v$event_name en
where se.event_id = en.event_id and en.name = 'log file sync'
order by avg_time_waited desc)
where rownum < 4)
order by 1,3 desc,2,4;

PROMPT
PROMPT ORDERED BY WAIT_TIME_MILLI
PROMPT Note: This query won't work on 10.2 - ORA-942
select eh.snap_id, eh.instance_number inst, en.name, eh.wait_time_milli, eh.wait_count
from wrh$_event_histogram eh, v$event_name en
where eh.event_id = en.event_id and
(en.name in ('log file sync','gcs log flush sync',
'log file parallel write','wait for scn ack',
'log file switch completion','gc cr grant 2-way',
'gc buffer busy','gc current block 2-way')
or en.name like '%LGWR%' or en.name like '%LNS%')
and snap_id in (select snap_id from (
select se.snap_id, se.time_waited_micro/1000 / se.total_waits avg_time_waited
from wrh$_system_event se, v$event_name en
where se.event_id = en.event_id and en.name = 'log file sync'
order by avg_time_waited desc)
where rownum < 4)
order by 1,4,2,3 desc;

PROMPT
PROMPT ASH DETAILS FOR WORST MINUTES:
PROMPT
PROMPT APPROACH: If you cannot determine the problem from the data
PROMPT above, you may need to look at the details of what each session
PROMPT is doing during each 'bad' snap. Most likely you will want to
PROMPT note the times of the high log file sync waits, look at what
PROMPT LGWR is doing at those times, and go from there...
column program format a45 wra
column sample_time format a25 tru
column event format a30 tru
column time_waited format 999999.999
column p1 format a40 tru
column p2 format a40 tru
column p3 format a40 tru
select sample_time, inst_id inst, session_id, program, event, time_waited/1000 TIME_WAITED,
p1text||': '||p1 p1,p2text||': '||p2 p2,p3text||': '||p3 p3
from gv$active_session_history
where to_char(sample_time,'Mondd_hh24mi') in (select
to_char(sample_time,'Mondd_hh24mi')
from gv$active_session_history
where event = 'log file sync'
group by to_char(sample_time,'Mondd_hh24mi'), inst_id
having avg(time_waited)/1000 > &&threshold)
and time_waited > 0.5
order by 1,2,3,4,5;

select to_char(sysdate,'Mondd hh24:mi:ss') TIME from dual;

spool off

PROMPT
PROMPT OUTPUT FILE IS: lfsdiag_&&dbname&&timestamp&&suffix
PROMPT

该脚本输出结果大致如下：

LFSDIAG DATA FOR DBM_Oct10_1307
Note: All timings are in milliseconds (1000 milliseconds = 1 second)

IMPORTANT PARAMETERS RELATING TO LOG FILE SYNC WAITS:

   INST_ID NAME                                     VALUE
---------- ---------------------------------------- ----------------------------------------
         1 commit_logging
         1 commit_point_strength                    1
         1 commit_wait
         1 commit_write
         1 log_archive_local_first                  TRUE
         1 log_archive_max_processes                4
         1 log_archive_min_succeed_dest             1
         1 log_archive_start                        FALSE
         1 log_archive_trace                        0
         2 commit_logging
         2 commit_point_strength                    1
         2 commit_wait
         2 commit_write
         2 log_archive_local_first                  TRUE
         2 log_archive_max_processes                4
         2 log_archive_min_succeed_dest             1
         2 log_archive_start                        FALSE
         2 log_archive_trace                        0

ASH THRESHOLD...

This will be the threshold in milliseconds for average log file sync
times. This will be used for the next queries to look for the worst
'log file sync' minutes. Any minutes that have an average log file
sync time greater than the threshold will be analyzed further.

THRESHOLD_IN_MS
---------------
           .000

ASH WORST MINUTES FOR LOG FILE SYNC WAITS:

APPROACH: These are the minutes where the avg log file sync time
was the highest (in milliseconds).

MINUTE          INST_ID EVENT                            TOTAL_WAIT_TIME      WAITS   AVG_TIME_WAITED
------------ ---------- ------------------------------ ----------------- ---------- -----------------
Oct01_0111            2 log file sync                               .807          1              .807
Oct02_0600            2 log file sync                              4.308          1             4.308
Oct09_0043            2 log file sync                            999.805          1           999.805

ASH LFS BACKGROUND PROCESS WAITS DURING WORST MINUTES:

APPROACH: What is LGWR doing when 'log file sync' waits
are happening? LMS info may be relevent for broadcast
on commit and LNS data may be relevant for dataguard.
If more details are needed see the ASH DETAILS FOR WORST
MINUTES section at the bottom of the report.

MINUTE       INST PROGRAM                                  EVENT                            TOTAL_WAIT_TIME      WAITS   AVG_TIME_WAITED
------------ ---- ---------------------------------------- ------------------------------ ----------------- ---------- -----------------
Oct02_0600      2 oracle@racnode1.us.oracle.com (LGWR)    log file parallel write                    4.088          1             4.088
Oct02_0600      2 oracle@racnode1.us.oracle.com (M000)    log file sync                              4.308          1             4.308
Oct09_0043      2 oracle@racnode1.us.oracle.com (LGWR)    log file parallel write                 1000.738          1          1000.738
Oct09_0043      2 sqlplus@racnode1.us.oracle.com (TNS V1- log file sync                            999.805          1           999.805
                  V3)


HISTOGRAM DATA FOR LFS AND OTHER RELATED WAITS:

APPROACH: Look at the wait distribution for log file sync waits
by looking at "wait_time_milli". Look at the high wait times then
see if you can correlate those with other related wait events.

   INST_ID EVENT                                    WAIT_TIME_MILLI WAIT_COUNT
---------- ---------------------------------------- --------------- ----------
         2 wait for scn ack                                       1          0
         2 wait for scn ack                                       2          0
         2 wait for scn ack                                       4          0
         2 wait for scn ack                                       8          1
         1 log file sync                                          1      10247
         1 log file sync                                          2        435
         1 log file sync                                          4        122
         1 log file sync                                          8         33
         1 log file sync                                         16          4
         1 log file sync                                         32          2
         1 log file sync                                         64          2
         1 log file sync                                        128          1
         1 log file sync                                        256          1
         1 log file sync                                        512          0
....................................
Oracle 数据技术 浅谈oracle技术系列 等待事件 | Guang Cai Li |

浅谈log file sync等待事件诊断（二）

原因3：用户提交过于频繁导致log file sync

在这种情况下，过多的 commit 活动可能会导致性能问题，因为把 redo 从日志缓冲区刷新到重做日志可能会导致等待’log file sync’。
如果’log file sync’的平均等待时间比’log file parallel write’高很多，这意味着大部分时间等待不是由于等待 redo 的写入，因而问题的原因不是 IO 慢导致。，其他时间可能是 CPU 活动竞争，而且是过多的 commit 导致的最常见的竞争。此外，如果’log file sync’的平均等待时间低，但等待次数高，那么应用程序可能 commit 过于频繁。

在 AWR 或 Statspack 报告中，如果每次 commit/rollback 的平均 user calls（”user calls/(user commits+user rollbacks)”） 小于 30， 表明 commit 过于频繁。
建议

  • 如果有很多短事务，看是否可能把这些事务组合在一起，从而减少 commit 操作。 因为每一个 commit 都必须收到相关 REDO 已写到磁盘上的确认，额外的 commit 会显著的增加开销。虽然 Oracle 可以将某些 commit 组合在一起，通过事务的批处理来减少commit的总体数量还是可以带来非常有益的效果。
  • 看看是否有操作可以使用 COMMIT NOWAIT 选项 （使用前应明白该选项会带来的后果）。
  • 看看是否有操作可以使用 NOLOGGING/ UNRECOVERABLE 选项完成（在不追求可恢复的情况下）。

 

经过已经分析，大概可以得出一个思路，尽量结合与lgwr有关的等待事件一起结合起来定位问题，此时应该检查awr或者statspack的等待事件。

11g新特性：
在oracle 11.2版本中引入了 Adaptive Log File sync，由参数_use_adaptive_log_file_sync控制，该参数在11.2.0.1和11.2.0.2默认设置为 false。
从 11.2.0.3 开始默认是 true。 当启用时，Oracle 可以在两种方法之间切换：

Post/wait，传统发布写重做日志完成的方法
Polling，一种新的方法，其中前台进程会检查 LGWR 是否已写完成。

该特性在一定情况下也会造成log file sync等待大量增加。

当log file sync等待事件是由于RAC节点之间SCN同步引起的，其解决方法如下：
1、检查LMS进程数量是否足够。
2、检查系统CPU资源是否足够。
3、检查RAC节点之间的私有通信是否正常。
4、设置隐含参数_immediate_commit_propagation为false，禁用immediate commit propagation特性。
RAC节点之间CR块传递
Oracle为了保证Instance Recovery实例恢复机制，而要求每一个current block在本地节点local instance被修改后(modify/update) 必须要将该current block相关的redo 写入到logfile 后（要求LGWR必须完成写入后才能返回)，才能由LMS进程传输给其他节点使用。

Oracle 数据技术 浅谈oracle技术系列 等待事件 | Guang Cai Li | |   log file sync