strace对lgwr的探查

LGWR进程调用

    3s
    commit;
    日志缓存达到1M
    大于1/3log_buffer
    日志优化先、

准备：准备匿名过程

begin
for i in 1 .. 1000000
loop
insert into t1 values(i,'AAAAAAAAAAA'||i);
end loop;
commit;
end;
/

用于循环插入 1000000条数据

1.查寻lgwr的进程PID

[oracle@localhost ~]$ ps -ef |grep lgwr
oracle 4446 4399 0 00:21 pts/1 00:00:00 grep lgwr
oracle 5248 1 0 Oct27 ? 00:00:01 ora_lgwr_orcl

2.从上图中看出lgwr的pid为5248。使用strace 跟踪

[oracle@localhost ~]$ strace -fr -o /tmp/lgwrtest.log -p 5248
Process 5248 attached - interrupt to quit
Process 5248 detached

3.[oracle@jfdb ~]$ tail -f /tmp/lgwr8702.log

4.可以过滤出pwrite函数，次函数为为向日志文件写日志

5.观察跟踪日志的过程

5248 0.000179 pwrite(259, "\1\"\0\0\251\216\0\0\16\0\0\0\20\200\200s8\1\0\0\5\1\0\0\257\263\22\0\1\0\22\0"..., 1048576, 18698752) = 1048576
5248 0.012716 pwrite(259, "\1\"\0\0\251\226\0\0\16\0\0\0\0\201>X\3\0\377\377&\f\300\0\320\263\22\0\0\0\0\0"..., 512, 19747328) = 512
5248 0.000095 pwrite(259, "\1\"\0\0\252\226\0\0\16\0\0\0\20\200\234\0168\1\0\0\5\0\0\0\321\263\22\0\1\0\0\0"..., 1048576, 19747840) = 1048576
5248 0.004920 pwrite(259, "\1\"\0\0\252\236\0\0\16\0\0\0\330\200\305\327\5\0\36\0\227\3\0\0\274\0G\0\365)\1\0"..., 512, 20796416) = 512
5248 0.000136 pwrite(259, "\1\"\0\0\253\236\0\0\16\0\0\0\20\200\237.8\1\0\0\5\0\0\0\362\263\22\0\1\0\0\0"..., 727040, 20796928) = 727040
5248 0.000091 pwrite(259, "\1\"\0\0007\244\0\0\16\0\0\0\20\200\7\332`\0\0\0\5\3\0\0\f\264\22\0\1\0\366\0"..., 2048, 21523968) = 2048
5248 0.000042 pwrite(259, "\1\"\0\0;\244\0\0\16\0\0\0\20\200\312\23p\0\0\0\5A\0\0\17\264\22\0\1\0\0\0"..., 512, 21526016) = 512
5248 0.000144 pwrite(259, "\1\"\0\0<\244\0\0\16\0\0\0\20\200\ncl\0\0\0\5\0\0\0\21\264\22\0\1\0\0\0"..., 396288, 21526528) = 396288
5248 0.004110 pwrite(259, "\1\"\0\0B\247\0\0\16\0\0\0\260\200\202\32\0\0\0\0i\f\300\0\274\0\20\0i\4\0\1"..., 652800, 21922816) = 652800
5248 0.000186 pwrite(259, "\1\"\0\0=\254\0\0\16\0\0\0\20\200\250\3138\1\0\0\5\0\0\0008\264\22\0\1\0L\0"..., 1048576, 22575616) = 1048576
5248 0.019982 pwrite(259, "\1\"\0\0=\264\0\0\16\0\0\0\260\200\261\222\0\0\0\0\235\f\300\0\275\0I\0G\4\0\1"..., 512, 23624192) = 512
5248 0.000093 pwrite(259, "\1\"\0\0>\264\0\0\16\0\0\0\20\200{\2018\1\0\0\5\3\0\0Y\264\22\0\1\0\2\1"..., 1048576, 23624704) = 1048576
5248 0.009052 pwrite(259, "\1\"\0\0>\274\0\0\16\0\0\0\20\200d\377\f\1\0\0\1\0\0\0z\264\22\0\10\0:\0"..., 512, 24673280) = 512
5248 0.000100 pwrite(259, "\1\"\0\0?\274\0\0\16\0\0\0\20\200'\3338\1\0\0\5\2\0\0{\264\22\0\1\0\0\1"..., 902656, 24673792) = 902656
5248 0.008642 pwrite(259, "\1\"\0\0\"\303\0\0\16\0\0\0\344\200\3r\24\0\0\0D\0\252\0\"\0\0\0\5\0\36\0"..., 145920, 25576448) = 145920
5248 0.000168 pwrite(259, "\1\"\0\0?\304\0\0\16\0\0\0\20\200f\2408\1\0\0\5\f\0\0\234\264\22\0\1\0\0\0"..., 1048576, 25722368) = 1048576
5248 0.018422 pwrite(259, "\1\"\0\0?\314\0\0\16\0\0\0\20\200+9\f\1\0\0\1\3\0\0\277\264\22\0X\0\1\0"..., 9728, 26770944) = 9728
5248 0.000130 pwrite(259, "\1\"\0\0R\314\0\0\16\0\0\0\20\200\316\0248\1\0\0\5A\0\0\301\264\22\0\1\0R\0"..., 1048576, 26780672) = 1048576
5248 0.012305 pwrite(259, "\1\"\0\0R\324\0\0\16\0\0\0D\200m\200\210\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512, 27829248) = 512
5248 0.000094 pwrite(259, "\1\"\0\0S\324\0\0\16\0\0\0\20\200ZX8\1\0\0\5\0\0\0\343\264\22\0\1\0\0\0"..., 1048576, 27829760) = 1048576
5248 0.000095 pwrite(259, "\1\"\0\0S\334\0\0\16\0\0\0\20\200\356\"8\1\0\0\5\0\0\0\4\265\22\0\1\0\22\0"..., 351744, 28878336) = 351744
5248 0.003979 pwrite(259, "\1\"\0\0\2\337\0\0\16\0\0\0008\200\352A\0\0\0\0\32\0r\0\0\0\0\0\1\0\36\0"..., 697344, 29230080) = 697344
5248 0.000095 pwrite(259, "\1\"\0\0T\344\0\0\16\0\0\0\20\200\17\2438\1\0\0\5\0\0\0&\265\22\0\1\0\0\0"..., 1048576, 29927424) = 1048576
5248 0.010336 pwrite(259, "\1\"\0\0T\354\0\0\16\0\0\0\34\200\2658AAA231998\r\300\0\0\0\0\0"..., 512, 30976000) = 512
5248 0.000094 pwrite(259, "\1\"\0\0U\354\0\0\16\0\0\0\20\200\204\3158\1\0\0\5\2\0\0L\265\22\0\1\0\0\1"..., 1048576, 30976512) = 1048576
5248 0.009271 pwrite(259, "\1\"\0\0U\364\0\0\16\0\0\0\260\200\7\261\0\0\0\0\240\r\300\0\277\0`\0\342\4\0\1"..., 512, 32025088) = 512
5248 0.000099 pwrite(259, "\1\"\0\0V\364\0\0\16\0\0\0\20\200~:8\1\0\0\5\264\0\0o\265\22\0\1\0\365)"..., 858112, 32025600) = 858112
5248 0.097013 pwrite(259, "\1\"\0\0\342\372\0\0\16\0\0\0`\200\221\307\277\0+\0\317\4\0\1\252\0\0\1\372\22\2\1"..., 190464, 32883712) = 190464
5248 0.000154 pwrite(259, "\1\"\0\0V\374\0\0\16\0\0\0\20\2008\2158\1\0\0\5\0\0\0\221\265\22\0\1\0\365)"..., 1048576, 33074176) = 1048576
5248 0.044251 pwrite(259, "\1\"\0\0V\4\1\0\16\0\0\0008\200(\210\0\0\0\0\32\0\16\0\0\0\0\0\1\0\0\0"..., 1048576, 34122752) = 1048576
5248 0.010451 pwrite(259, "\1\"\0\0V\f\1\0\16\0\0\0`\200\235\f\300\0\v\0\315\4\0\1\252\0\0\1\372\22\2\1"..., 358400, 35171328) = 358400
5248 0.000144 pwrite(259, "\1\"\0\0\22\17\1\0\16\0\0\0\20\200:\3338\1\0\0\0055\0\0\340\265\22\0\1\0\0\0"..., 1007616, 35529728) = 1007616
5248 0.010915 pwrite(259, "\1\"\0\0\302\26\1\0\16\0\0\0\334\200\6\37\"\0\0\0\5\0\36\0\227\3\0\0\300\0\17\0"..., 41472, 36537344) = 41472
5248 0.000117 pwrite(259, "\1\"\0\0\23\27\1\0\16\0\0\0\20\200xY8\1\0\0\5\0\0\0\3\266\22\0\1\0L\0"..., 1048576, 36578816) = 1048576
5248 0.000096 pwrite(259, "\1\"\0\0\23\37\1\0\16\0\0\0\20\200+I8\1\0\0\5\0\0\0$\266\22\0\1\0\10\0"..., 1048576, 37627392) = 1048576
5248 0.000096 pwrite(259, "\1\"\0\0\23'\1\0\16\0\0\0\20\200\274R8\1\0\0\5\4\0\0F\266\22\0\1\0\2\1"..., 1048576, 38675968) = 1048576
5248 0.010101 pwrite(259, "\1\"\0\0\23/\1\0\16\0\0\0\0\201\21\213\3\0\377\377\216\16\300\0f\266\22\0\0\0\0\0"..., 512, 39724544) = 512
5248 0.000051 pwrite(259, "\1\"\0\0\24/\1\0\16\0\0\0\20\200\216\0038\1\0\0\5\0\0\0g\266\22\0\1\0\36\0"..., 35328, 39725056) = 35328
5248 0.000047 pwrite(259, "\1\"\0\0Y/\1\0\16\0\0\0\20\200\214\350`\0\0\0\5\4\0\0j\266\22\0\1\0\2\1"..., 1024, 39760384) = 1024
5248 0.000046 pwrite(259, "\1\"\0\0[/\1\0\16\0\0\0\20\200\202\245`\0\0\0\5\16\0\0l\266\22\0\1\0\0\1"..., 1024, 39761408) = 1024
5248 0.000043 pwrite(259, "\1\"\0\0]/\1\0\16\0\0\0\20\200\327\300`\0\0\0\5\16\0\0o\266\22\0\1\0\0\0"..., 1024, 39762432) = 1024

 

仔细观察可以发现，里面的1048576为最大值

SQL> select 1048576/1024/1024 from dual;

发现正好是1M。当日志缓存达到1M时即会记执行lgwr进程写日志。

3S很容易可以观察出来，刷新的时间间隔