LOG FILE SYNC概述（第六篇）

最新推荐文章于 2023-03-02 11:00:02 发布

cotchte0421

最新推荐文章于 2023-03-02 11:00:02 发布

阅读量182

点赞数

PL/SQL commit优化

传统情况下，当用户发出commit后，用户会话会等待log file sync直到lgwr写完成。LGWR写完成后，通知处于前台进程继续处理后面的操作。这个机制保障了事务的持久性，满足了事务ACID的D。但是PL/SQL不是这么工作的：PL/SQL里的commit 操作不会等待lgwr写完成就可以继续处理后面的操作。简单的看个例子：

begin
for r in (select id from t1 where mod(id, 20) = 0) loop
update t1 set small_no = small_no + .1 where id = r.id;
commit;
end loop;
end;
/

查看session 和 sys相关的统计信息如下：

user commits (session statistic)    25
messages sent (session statistic)    6
redo synch writes(session statistic) 1
log file sync (session events)       1
messages received (lgwr statistic)    6
redo writes (lgwr statistic)          6
log file parallel write (lgwr events)  6

Lgwr仅仅写了6次（log file parallel write），用户会话仅仅等待了log file sync一次。那意味着会话发出commit命令后，并没有停下来等待lgwr写完成，就继续处理后面的事务了。用户会话没有遵守事务的持久化原则！！如果实例在PL/SQL处理的过程中crash，那么某些提交的事务是不可恢复的。Oracle对此有一个貌似合理的解释，在PL/SQL没有处理完毕之前，你不知道已经提交了多少次，Oracle不会使他们可恢复，只有在PL/SQL结束的时候，增加redo sync writes次数和前台进程进入log file sync等待。在进行PL/SQL处理期间，不停的查看等待事件，后台看不到任何的log file sync等待。还有就是统计资料里显示了会话总共向lgwr发送了6次message sent请求（请求写日志），lgwr也接受到了6次message recived信息，并且写了6次（log file parallel write）。你可能会问，到底多久，会话发送一次写请求？每次前台进程给LGWR发送写请求前，会去持有redo writing latch，然后检查lgwr是不是已经在处理写请求了，如果lgwr已经在写了，前台进程不会向LGWR发送请求，也不会等待log fil sync，直接继续完成后续的操作，如果lgwr没在写，前台进程通知lgwr去写，但是不会等待log file sync，还是继续完成后续的操作，只有在PL/SQL结束的时候，才会最终等待一次log file sync。因此如果你的磁盘写的速率足够快，那么lgwr就会被post的次数越多，成正比的关系。还有如果你的CPU足够强，那么PL/SQL块loop的时间就足够小，时间小了，那么lgwr被post的次数也就少了，成反比的关系（在磁盘写速率一定的情况下）。
值得注意的是，如果PL/SQL里包含了DBLINK，那么就会使用传统的提交方式，不会产生出这样的“异常”。
最后提醒一句：虽然PL/SQL只有在结束的时候才会等待lgwr写完成，产生log file sync等待，但是不要认为，在PL/SQL运行过程中，实例crash掉，此次PL/SQL处理的所有事务就会丢失，不是这样的，只是丢失部分，pl/sql在运行过程中，会话是一直检查lgwr是不是在工作的，如果没在工作，就发送写请求给lgwr的（message sent），lgwr接收到写请求后，就要写日志，只要是被写进了日志文件的事务就是可恢复的。也就是说，虽然前台没有等待log file sync，但是后台其实一直是在忙着处理你的事务日志的。

log file sync与buffer busy waits

事务在进行提交的时候，对事务修改的，还在内存里的块做commit cleanout，其实主要就是设置ITL槽位里的commit scn，不会去清楚lb信息。ORACLE在进行commit cleanout期间，会获取相关buffer的buffer pin，而且是排他模式获取，这个pin直到lgwr把日志刷入到磁盘才释放，如果在此期间，有进程对相关的buffer进行select/update/insert就会造成buffer busy waits。因此如果你的系统log file sync指标很高，也可能会导致一定程度的buffer busy waits等待事件。

被误导的平均数

平均数有时候是非常害人的，例如臭名昭彰的buffer cache命中率，命中率本身就是一种平均数思维。这里有一个有趣的log file sync和log file parallel write跟平均数有关的一个案例。

任何ORACLE DBA都应该是一个AWR报告的粉丝，我也不例外，经常能从AWR报告中发现一些系统的蛛丝马迹。如下面的一份报告：

Per Second Per Transaction

---------- ---------------

Redo size: 140,604.47 325.65

Logical reads: 16,712.80 38.71

Block changes: 904.42 2.09

Physical reads: 7.59 0.02

Physical writes: 70.76 0.16

User calls: 2,069.02 4.79

Parses: 342.31 0.79

Hard parses: 0.07 0

Sorts: 52.54 0.12

Logons: 0.47 0

Executes: 342.82 0.79

Transactions: 431.77

从上面的profile中可以看出这个系统的负载不大，逻辑读和物理读都不搞，是一个良好的使用了绑定变量的系统，因为硬解析数很低，每秒的执行次数也很低只有300多次，系统的事务数比较高，每秒400多次。而且系统的回滚率稍微有点高，因为事务数明显的大过了执行次数，等等。

我们继续看等待事件部分的AWR报告：

Event Waits Time(s) AvgWait % Total Wait Class

----- ----- ------- ------- ------- ----------

log file sync 357,552 22,427 63 90.4 Commit

CPU time 1,636 6.6

log file parallel write 275,265 972 4 3.9 System I/O

read by other session 7,848 533 68 2.1 User I/O

db file parallel write 87,473 325 4 1.3 System I/O

从等待事件来看，这个系统遭遇着严重的log file sync等待，每次log file sync等待的时间已经达到了63ms，准确的说应该是，log file sync的平均等待时间已经达到了63ms。但是log file parallel write等待事件的平均等待时间只有4ms。两者差了59ms之多，4ms的log file parallel write其实不算高，就像我们前面提到的，如果log file sync的等待时间明显大于log file parallel write时间的话，那么最好检查一下CPU资源是否富足。通过sar查看AWR报告采样时间段内的CPU资源使用率，非常的低，10%不到。那原因隐藏在那呢？

首先我们需要明确，一次log file parallel write可能会导致多次log file sync，因为log file parallel write是发生在后台进程lgwr上的等待事件，而log file sync是前台用户进程的等待事件，非常可能多个用户进程同时等待log file sync等待lgwr写（group commit的作用）。

接着刚才的案例，通过查看lgwr的trace文件发现，日志里每隔几分钟就会出现写超时警告，这是10G时出现的功能，莫非是主机的raid卡的cache被写穿了？但是如果是写有问题，为什么log file parallel write的指标值很正常只有4ms呢？这主要的原因是，慢写是非常慢的，大多数的写都是非常快的。我们可以算一笔账：

3000次写非常快，每次花费0.5ms

20次写速度极慢，每次花费1000ms

2000次写，速度正常，每次花费1ms

总共花费的时间为：3000*0.5+20*1000+2000*1=23500 ms

平均的响应时间为：23500/5020=4.68ms

这个数字跟AWR报告中看到的数字非常接近了。但是仔细观察会发现，20次极慢的写时间占了总时间的85%，但是它的执行次数占总次数的比例只有0.4%。

我们接下来看log file sync受平均数影响的程度。我们来计算一下每次等待1000ms的log file parallel write等待的时候，log file sync等待了多长时间。除去回滚的事务，我们可以认为系统每秒的提交数为342次。我们假设在这1000ms内，这些事务是到达的，按照三角形面积的计算公式：

1000*342/2=171000ms。

等待一次1000ms的log file parallel write要等待171000ms的log file sync。当等待1000ms的log file parallel write结束后，又开始等待快速的log file parallel write

按照如上的算法：

· 3000 次log file sync等待在0.5ms = 1096ms

· 20次log file sync等待在1000ms= 3,420,000 ms

· 2000次log file sync等待在1ms = 2923ms

· 这总的等待次数是5000+20*342=11840，对比5020此的log file parallel write。总共的等待时间为3424019，我们算一下平均数：为289ms。对比4.68ms的log file parallel write

Adaptive Log File Sync

Adaptive Log File sync was introduced in 11.2. The parameter controlling this feature, _use_adaptive_log_file_sync, is set to false by default in 11.2.0.1 and 11.2.0.2.

In 11.2.0.3 the default is now true. When enabled, Oracle can switches between the 2 methods:

· Post/wait, traditional method for posting completion of writes to redo log

LGWR explicitly posts all processes waiting for the commit to complete.
The advantage of the post/wait method is that sessions should find out almost immediately when the redo has been flushed to disk.

· Polling, a new method where the foreground process checks if the LGWR has completed the write.

Foreground processes sleep and poll to see if the commit is complete.
The advantage of this new method is to free LGWR from having to inform many processes waiting on commit to complete thereby freeing high CPU usage by the LGWR.

when mode switches, it will write message to LGWR trace file.

*** 2012-10-02 08:15:47.049
kcrfw_update_adaptive_sync_mode: post->poll long#=316 sync#=1719 sync=247657
poll=12382 rw=6191 rw+=13890 ack=0 min_sleep=10023

But per my experience, “Polling” mode will cause higher average wait time of “log file sync” and is not a stable LGWR algorithm for heavy OLTP workload. It can be disabled by “alter system”.

Reference

12C在Oracle 11g中 Data Guard的redo传输工作主要由以下3组后台进程实现：

ARCi (FAL – archived redo shipping, ping, local only archivals)

NSAi (async) 12.1 name: TTnn ,

NSSi (sync) –– live redo shipping

但从版本12c开始使用TTnn 例如TT00进程来负责async 异步的redo传输。另一个后台进程TMON来负责做Redo transport monitor。

SQL> select banner from v$version where rownum=1;

BANNER

--------------------------------------------------------------------------------

Oracle Database 12c Enterprise Edition Release 12.1.0.1.0 - 64bit Production

SQL> select program,pid from v$process where program like '%TMON%' or Program like '%TT%';

PROGRAM PID