strace 进程的trace内容

oracle培训：http://www.cuug.com/
我们再来看下strace 该进程的trace内容是如何的 ：

—-fd 信息

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31

[root@12c_single ~]# cd /proc/4192/fd [root@12c_single fd]# ls -ltr total 0 lr-x------ 1 oracle oinstall 64 Jul  7 12:06 9 -> /dev/urandom lr-x------ 1 oracle oinstall 64 Jul  7 12:06 8 -> /dev/urandom lr-x------ 1 oracle oinstall 64 Jul  7 12:06 7 -> /dev/zero lrwx------ 1 oracle oinstall 64 Jul  7 12:06 6 -> anon_inode:[eventpoll] lr-x------ 1 oracle oinstall 64 Jul  7 12:06 5 -> /proc/4192/fd lr-x------ 1 oracle oinstall 64 Jul  7 12:06 4 -> /oracle/product/12.1/db_1/rdbms/mesg/oraus.msb lr-x------ 1 oracle oinstall 64 Jul  7 12:06 3 -> /dev/null lrwx------ 1 oracle oinstall 64 Jul  7 12:06 270 -> /oracle/oradata/orcl/killdb/sysaux01.dbf lrwx------ 1 oracle oinstall 64 Jul  7 12:06 269 -> /oracle/oradata/orcl/killdb/system01.dbf lrwx------ 1 oracle oinstall 64 Jul  7 12:06 268 -> /oracle/oradata/orcl/roger01.dbf lrwx------ 1 oracle oinstall 64 Jul  7 12:06 267 -> /oracle/oradata/orcl/pdborcl/example01.dbf lrwx------ 1 oracle oinstall 64 Jul  7 12:06 266 -> /oracle/oradata/orcl/pdborcl/SAMPLE_SCHEMA_users01.dbf lrwx------ 1 oracle oinstall 64 Jul  7 12:06 265 -> /oracle/oradata/orcl/pdborcl/sysaux01.dbf lrwx------ 1 oracle oinstall 64 Jul  7 12:06 264 -> /oracle/oradata/orcl/pdborcl/system01.dbf lrwx------ 1 oracle oinstall 64 Jul  7 12:06 263 -> /oracle/oradata/orcl/pdbseed/sysaux01.dbf lrwx------ 1 oracle oinstall 64 Jul  7 12:06 262 -> /oracle/oradata/orcl/pdbseed/system01.dbf lrwx------ 1 oracle oinstall 64 Jul  7 12:06 261 -> /oracle/oradata/orcl/users01.dbf lrwx------ 1 oracle oinstall 64 Jul  7 12:06 260 -> /oracle/oradata/orcl/undotbs01.dbf lrwx------ 1 oracle oinstall 64 Jul  7 12:06 259 -> /oracle/oradata/orcl/sysaux01.dbf lrwx------ 1 oracle oinstall 64 Jul  7 12:06 258 -> /oracle/fast_recovery_area/orcl/control02.ctl lrwx------ 1 oracle oinstall 64 Jul  7 12:06 257 -> /oracle/oradata/orcl/control01.ctl lrwx------ 1 oracle oinstall 64 Jul  7 12:06 256 -> /oracle/oradata/orcl/system01.dbf l-wx------ 1 oracle oinstall 64 Jul  7 12:06 2 -> /dev/null l-wx------ 1 oracle oinstall 64 Jul  7 12:06 13 -> pipe:[24450] lrwx------ 1 oracle oinstall 64 Jul  7 12:06 11 -> /oracle/admin/orcl/adump/orcl_ora_4192_20130707113215690516143795.aud lr-x------ 1 oracle oinstall 64 Jul  7 12:06 10 -> pipe:[24449] l-wx------ 1 oracle oinstall 64 Jul  7 12:06 1 -> /dev/null lr-x------ 1 oracle oinstall 64 Jul  7 12:06 0 -> /dev/null

—-读操作

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21

[root@12c_single ~]# cat /tmp/4192.log |grep pread 4192       0.002157 pread(257, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\241\360\0\0\0\0\0\0\0\0\20\fM\212IP"..., 16384, 16384) = 16384 4192       0.000113 pread(258, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\241\360\0\0\0\0\0\0\0\0\20\fM\212IP"..., 16384, 16384) = 16384 4192       0.000284 pread(257, "\25\302\0\0\20\0\0\0\225\7\0\0\377\377\1\4Y\7\0\0\200\3\0\0\0\0\0\0\0\0\0\0"..., 16384, 262144) = 16384 ....... 4192       0.000050 pread(257, "\25\302\0\0Y\0\0\0\213\7\0\0\377\377\1\4\341O\0\0\3\0\3\0\0\0\0\0\0\0/o"..., 16384, 1458176) = 16384 4192       0.000052 pread(257, "\25\302\0\0\377\2\0\0\225\7\0\0\377\377\1\4\252\262\0\0\33\0\6\0\335\7\0\0\0\0\0\0"..., 16384, 12566528) = 16384 4192       0.000054 pread(260, "\v\242\0\0\1\0\200\1\0\0\0\0\0\0\1\0047\300\0\0\0\0\0\0\0\0\20\fM\212IP"..., 8192, 8192) = 8192 4192       0.000250 pread(257, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\271\203\0\0\0\0\0\0\0\0\20\fM\212IP"..., 16384, 16384) = 16384 4192       0.000053 pread(258, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\271\203\0\0\0\0\0\0\0\0\20\fM\212IP"..., 16384, 16384) = 16384 ....... 4192       0.000097 pread(257, "\25\302\0\0\30\0\0\0\230\7\0\0\377\377\1\4.\316\0\0\0\0\0\0\0 \0\0\16\0\0\0"..., 16384, 393216) = 16384 4192       0.000123 pread(261, "\v\242\0\0\1\0\200\1\0\0\0\0\0\0\1\0047\300\0\0\0\0\0\0\0\0\20\fM\212IP"..., 8192, 8192) = 8192 4192       0.000105 pread(257, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\337\203\0\0\0\0\0\0\0\0\20\fM\212IP"..., 16384, 16384) = 16384 4192       0.000060 pread(258, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\337\203\0\0\0\0\0\0\0\0\20\fM\212IP"..., 16384, 16384) = 16384 4192       0.000055 pread(257, "\25\302\0\0\20\0\0\0\231\7\0\0\377\377\1\4YO\0\0\200\3\0\0\0\10\0\0\0\0\0\0"..., 16384, 262144) = 16384 ........ 4192       0.000058 pread(257, "\25\302\0\0\17\0\0\0\232\7\0\0\377\377\1\4\306\3\0\0\0\7\0\0\0\0\0\0\0\0\0\0"..., 16384, 245760) = 16384 4192       0.000402 pread(257, "\25\302\0\0\21\0\0\0\232\7\0\0\377\377\1\4\254\275\0\0\0\0\0\0\0\0\0\0\315>\3240"..., 16384, 278528) = 16384   ----写操作

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35

[root@12c_single ~]# cat /tmp/4192.log |grep pwrite 4192       0.000231 pwrite(257, "\25\302\0\0\30\0\0\0\226\7\0\0\377\377\1\4)\316\0\0\0\0\0\0\0 \0\0\16\0\0\0"..., 16384, 393216) = 16384 4192       0.001686 pwrite(258, "\25\302\0\0\30\0\0\0\226\7\0\0\377\377\1\4)\316\0\0\0\0\0\0\0 \0\0\16\0\0\0"..., 16384, 393216) = 16384 ...... 4192       0.001631 pwrite(258, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\271\203\0\0\0\0\0\0\0\0\20\fM\212IP"..., 16384, 16384) = 16384 4192       0.000057 pwrite(261, "\v\242\0\0\1\0\200\1\0\0\0\0\0\0\1\0046\300\0\0\0\0\0\0\0\0\20\fM\212IP"..., 8192, 8192) = 8192 4192       0.000057 pwrite(257, "\25\302\0\0Y\0\0\0\227\7\0\0\377\377\1\4\333O\0\0\3\0\3\0\0\0\0\0\0\0/o"..., 16384, 1458176) = 16384 4192       0.001907 pwrite(258, "\25\302\0\0Y\0\0\0\227\7\0\0\377\377\1\4\333O\0\0\3\0\3\0\0\0\0\0\0\0/o"..., 16384, 1458176) = 16384 4192       0.000076 pwrite(257, "\25\302\0\0\27\0\0\0\227\7\0\0\377\377\1\4\"\316\0\0\0\0\0\0\0 \0\0\16\0\0\0"..., 16384, 376832) = 16384 4192       0.001767 pwrite(258, "\25\302\0\0\27\0\0\0\227\7\0\0\377\377\1\4\"\316\0\0\0\0\0\0\0 \0\0\16\0\0\0"..., 16384, 376832) = 16384 4192       0.000058 pwrite(257, "\25\302\0\0\22\0\0\0\227\7\0\0\377\377\1\4\257\275\0\0\0\0\0\0\0\0\0\0\315>\3240"..., 16384, 294912) = 16384 4192       0.001790 pwrite(258, "\25\302\0\0\22\0\0\0\227\7\0\0\377\377\1\4\257\275\0\0\0\0\0\0\0\0\0\0\315>\3240"..., 16384, 294912) = 16384 4192       0.000503 pwrite(257, "\25\302\0\0\20\0\0\0\227\7\0\0\377\377\1\4YG\0\0\200\3\0\0\0\0\0\0\0\0\0\0"..., 16384, 262144) = 16384 4192       0.001587 pwrite(258, "\25\302\0\0\20\0\0\0\227\7\0\0\377\377\1\4YG\0\0\200\3\0\0\0\0\0\0\0\0\0\0"..., 16384, 262144) = 16384 4192       0.000062 pwrite(257, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\267\203\0\0\0\0\0\0\0\0\20\fM\212IP"..., 16384, 16384) = 16384 4192       0.001828 pwrite(258, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\267\203\0\0\0\0\0\0\0\0\20\fM\212IP"..., 16384, 16384) = 16384 4192       0.000383 pwrite(261, "\35\242\0\0\2\0\200\1\353\371\32\0\0\0\1\4\233N\0\0\6\0\0\0\10\0\0\0\0d\0\0"..., 1040384, 16384) = 1040384 4192       0.000439 pwrite(261, "!\242\0\0\201\0\200\1]\25\r\0\0\0\2\4\210\231\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 1056768) = 1048576 4192       0.000370 pwrite(261, "\6\242\0\0\1\1\200\1\313\364\32\0\0\0\2\4 \214\0\0\1\0\0\0sg\1\0\260\364\32\0"..., 1048576, 2105344) = 1048576 4192       0.000458 pwrite(261, " \242\0\0\201\1\200\1c\4\33\0\0\0\1\4w\340\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 3153920) = 1048576 4192       0.000353 pwrite(261, " \242\0\0\1\2\200\1e\4\33\0\0\0\1\4u\340\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 4202496) = 1048576 4192       0.000191 pwrite(261, " \242\0\0\201\2\200\1g\4\33\0\0\0\1\4s\340\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 5251072) = 1048576 ...... 4192       0.000386 pwrite(261, "\0\242\0\0\201b\200\1\0\0\0\0\0\0\1\5\1\304\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 206577664) = 1048576 4192       0.000426 pwrite(261, "\0\242\0\0\1c\200\1\0\0\0\0\0\0\1\5\201\305\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 207626240) = 1048576 4192       0.000399 pwrite(261, "\0\242\0\0\201c\200\1\0\0\0\0\0\0\1\5\1\305\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 208674816) = 1048576 4192       0.000269 pwrite(261, "\v\242\0\0\1\0\200\1\0\0\0\0\0\0\1\0047\300\0\0\0\0\0\0\0\0\20\fM\212IP"..., 8192, 8192) = 8192 4192       0.000081 pwrite(257, "\25\302\0\0\30\0\0\0\230\7\0\0\377\377\1\4.\316\0\0\0\0\0\0\0 \0\0\16\0\0\0"..., 16384, 393216) = 16384 4192       0.001666 pwrite(258, "\25\302\0\0\30\0\0\0\230\7\0\0\377\377\1\4.\316\0\0\0\0\0\0\0 \0\0\16\0\0\0"..., 16384, 393216) = 16384 ....... 4192       0.000225 pwrite(257, "\25\302\0\0\17\0\0\0\232\7\0\0\377\377\1\4\306\3\0\0\0\7\0\0\0\0\0\0\0\0\0\0"..., 16384, 245760) = 16384 4192       0.001583 pwrite(258, "\25\302\0\0\17\0\0\0\232\7\0\0\377\377\1\4\306\3\0\0\0\7\0\0\0\0\0\0\0\0\0\0"..., 16384, 245760) = 16384 4192       0.000066 pwrite(257, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\337\203\0\0\0\0\0\0\0\0\20\fM\212IP"..., 16384, 16384) = 16384 4192       0.001472 pwrite(258, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\337\203\0\0\0\0\0\0\0\0\20\fM\212IP"..., 16384, 16384) = 16384 [root@12c_single ~]#

我们可以发现对controlfile的读写,其次是会读undotbs.  写操作主要集中在controlfile和datafile 261上。
由于会触发检查点，那么更新controlfile是必然的，这点无容置疑.我们重点来看下对datafile 261的操作.

针对datafile 261的第1次写操作：
4192       0.000057 pwrite(261, “\v\242\0\0\1\0\200\1\0\0\0\0\0\0\1\0046\300\0\0\0\0\0\0\0\0\20\fM\212IP”…, 8192, 8192) = 8192

从offset 8192来看，这里是操作的datafile header block.

针对datafile 261的第2次写操作：
4192       0.000383 pwrite(261, “\35\242\0\0\2\0\200\1\353\371\32\0\0\0\1\4\233N\0\0\6\0\0\0\10\0\0\0\0d\0\0″…, 1040384, 16384) = 1040384

这里offset是16384,而我们的block size是8k,换句话讲是从第2个block开始写的. 后面的1043384表示写了127个block,跟我们10046 trace是完全能对上的.

大家注意后面每次针对datafile 261的写都是以128 block为单位的,也就是每次写单位是1m. 写完之后，最后再更新datafile header block.
所以,从strace process的结果来看,是多block写的,跟前面10046 trace的db file single write似乎有点不一致.