解密oracle mount过程

启动到nomount状态
startup nomount;
查看后台的核心进程 
ps -ef|grep -v grep|grep ora_
跟踪后台核心进程
strace -fr -o /tmp/10552.log -p 10552 --dbw0
strace -fr -o /tmp/10554.log -p 10554 --lgwr
strace -fr -o /tmp/10556.log -p 10556 --ckpt
strace -fr -o /tmp/10558.log -p 10558 --smon
strace -fr -o /tmp/10534.log -p 10534 --pmon
strace -fr -o /tmp/10560.log -p 10560 --reco
oradebug setmypid
oradebug event 10046 trace name context forever,level 12;
alter database mount;
oradebug event 10046 trace name context off;
 oradebug tracefile_name
 
 我们来查看dbw0的strace log
 10552      2.164211 mmap(NULL, 524288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_NORESERVE, 8, 0x73000) = 0x7f800d252000
10552      0.000099 mmap(0x7f800d252000, 327680, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 8, 0) = 0x7f800d252000
10552      0.000252 statfs("/home/oracle/app/oradata/oracleogg/control01.ctl", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=7294204, f_bfree=3142143, f_bavail=2771609, f_files=1855952, f_ffree=1694216, f_fsid={561672023, -1172758443}, f_namelen=255, f_frsize=4096}) = 0
10552      0.000058 open("/home/oracle/app/oradata/oracleogg/control01.ctl", O_RDWR|O_DSYNC) = 11
10552      0.000031 getrlimit(RLIMIT_NOFILE, {rlim_cur=64*1024, rlim_max=64*1024}) = 0
10552      0.000022 fcntl(11, F_DUPFD, 256) = 256
10552      0.000021 close(11)           = 0
10552      0.000020 fcntl(256, F_SETFD, FD_CLOEXEC) = 0
10552      0.000030 fstatfs(256, {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=7294204, f_bfree=3142143, f_bavail=2771609, f_files=1855952, f_ffree=1694216, f_fsid={561672023, -1172758443}, f_namelen=255, f_frsize=4096}) = 0
10552      0.000040 statfs("/home/oracle/app/oradata/oracleogg/control02.ctl", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=7294204, f_bfree=3142143, f_bavail=2771609, f_files=1855952, f_ffree=1694216, f_fsid={561672023, -1172758443}, f_namelen=255, f_frsize=4096}) = 0
10552      0.000036 open("/home/oracle/app/oradata/oracleogg/control02.ctl", O_RDWR|O_DSYNC) = 11
10552      0.000026 getrlimit(RLIMIT_NOFILE, {rlim_cur=64*1024, rlim_max=64*1024}) = 0
10552      0.000019 fcntl(11, F_DUPFD, 256) = 257
10552      0.000017 close(11)           = 0
10552      0.000018 fcntl(257, F_SETFD, FD_CLOEXEC) = 0
10552      0.000018 fstatfs(257, {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=7294204, f_bfree=3142143, f_bavail=2771609, f_files=1855952, f_ffree=1694216, f_fsid={561672023, -1172758443}, f_namelen=255, f_frsize=4096}) = 0
10552      0.000046 pread(256, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\216\375\0\0\0\0\0\0\0\4 \v\314d\261\210"..., 16384, 16384) = 16384
10552      0.000041 pread(257, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\216\375\0\0\0\0\0\0\0\4 \v\314d\261\210"..., 16384, 16384) = 16384
10552      0.000080 pread(256, "\25\302\0\0\20\0\0\0\351\24\0\0\377\377\1\4z\333\0\0\200G\0\0\0\0\0\0\0\0\0@"..., 16384, 262144) = 16384
10552      0.000101 pread(256, "\25\302\0\0\22\0\0\0\351\24\0\0\377\377\1\4\357\270\0\0\0\0\0\0\0\0\0\0\f\257\3144"..., 16384, 294912) = 16384
10552      0.000069 times({tms_utime=3, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 438775514
10552      0.000034 pread(256, "\25\302\0\0\30\0\0\0\343\24\0\0\377\377\1\0046\342\0\0\0^\1\0\0 \0\0\16\0\0\0"..., 16384, 393216) = 16384
10552      0.000077 pread(256, "\25\302\0\0\265\0\0\0&\0\0\0\377\377\1\4\366i\0\0\0\n\0\0\0 \0\0\36\0\7\0"..., 16384, 2965504) = 16384
10552      0.000046 getrusage(RUSAGE_SELF, {ru_utime={0, 38994}, ru_stime={0, 14997}, ...}) = 0
10552      0.000030 getrusage(RUSAGE_SELF, {ru_utime={0, 38994}, ru_stime={0, 14997}, ...}) = 0
正在读取控制文件,fd为256、257


查看操作系统层面
[root@oracle-ogg fd]# pwd
/proc/10552/fd
[root@oracle-ogg fd]# ls -ltr
total 0
lrwx------ 1 oracle dba 64 Sep 15 11:33 9 -> /home/oracle/app/oracle/product/11.2.0/dbhome_1/dbs/hc_oracleogg.dat
lr-x------ 1 oracle dba 64 Sep 15 11:33 8 -> /dev/zero
lr-x------ 1 oracle dba 64 Sep 15 11:33 7 -> /proc/10552/fd
lr-x------ 1 oracle dba 64 Sep 15 11:33 6 -> /home/oracle/app/oracle/product/11.2.0/dbhome_1/rdbms/mesg/oraus.msb
lr-x------ 1 oracle dba 64 Sep 15 11:33 5 -> /dev/null
lr-x------ 1 oracle dba 64 Sep 15 11:33 4 -> /dev/null
lr-x------ 1 oracle dba 64 Sep 15 11:33 3 -> /dev/null
lrwx------ 1 oracle dba 64 Sep 15 11:33 257 -> /home/oracle/app/oradata/oracleogg/control02.ctl
lrwx------ 1 oracle dba 64 Sep 15 11:33 256 -> /home/oracle/app/oradata/oracleogg/control01.ctl
l-wx------ 1 oracle dba 64 Sep 15 11:33 2 -> /dev/null
lrwx------ 1 oracle dba 64 Sep 15 11:33 10 -> /home/oracle/app/oracle/product/11.2.0/dbhome_1/dbs/lkORACLEOGG
l-wx------ 1 oracle dba 64 Sep 15 11:33 1 -> /dev/null
lr-x------ 1 oracle dba 64 Sep 15 11:33 0 -> /dev/null


两边一致
dbw0进程首先分别读取2个controlfile，顺序分别是control01、control02读取的是控制文件的头部块，也就是第二个block
pread(256, "\25\302\0\0\1\0\0\0\0\0\0\0\0\0\1\4\216\375\0\0\0\0\0\0\0\4 \v\314d\261\210"..., 16384, 16384) = 16384  ---第2个16384表示offset


lgwr进程的strace log 读写controlfile、打开alert.log信息
ckpt进程的日志 读取redo日志的信息
++++++++++我们最后来看看event 10046的trace信息
*** 2015-09-15 11:15:35.759
WAIT #0: nam='SQL*Net message from client' ela= 537366215 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1442286935759763
XCTEND rlbk=0, rd_only=1, tim=1442286935760583
=====================
PARSING IN CURSOR #139815001768920 len=20 dep=0 uid=0 oct=35 lid=0 tim=1442286935761297 hv=1913505115 ad='8e9a6278' sqlid='fr02x8dt0vjav'
alter database mount
END OF STMT
PARSE #139815001768920:c=1000,e=1395,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1442286935761293
WAIT #139815001768920: nam='rdbms ipc reply' ela= 8 from_process=12 timeout=900 p3=0 obj#=-1 tim=1442286935773613
WAIT #139815001768920: nam='rdbms ipc reply' ela= 2883 from_process=12 timeout=900 p3=0 obj#=-1 tim=1442286935776542
WAIT #139815001768920: nam='Disk file operations I/O' ela= 51 FileOperation=2 fileno=0 filetype=1 obj#=-1 tim=1442286935776768
WAIT #139815001768920: nam='Disk file operations I/O' ela= 10 FileOperation=2 fileno=1 filetype=1 obj#=-1 tim=1442286935776799
WAIT #139815001768920: nam='control file sequential read' ela= 24 file#=0 block#=1 blocks=1 obj#=-1 tim=1442286935776840
WAIT #139815001768920: nam='control file sequential read' ela= 5 file#=1 block#=1 blocks=1 obj#=-1 tim=1442286935776893
WAIT #139815001768920: nam='control file sequential read' ela= 135 file#=0 block#=3 blocks=8 obj#=-1 tim=1442286935777085
WAIT #139815001768920: nam='control file sequential read' ela= 30 file#=1 block#=3 blocks=8 obj#=-1 tim=1442286935777165


*** 2015-09-15 11:15:39.777
WAIT #139815001768920: nam='control file heartbeat' ela= 4000249 p1=0 p2=0 p3=0 obj#=-1 tim=1442286939777440
WAIT #139815001768920: nam='control file sequential read' ela= 55 file#=0 block#=3 blocks=8 obj#=-1 tim=1442286939777739
WAIT #139815001768920: nam='control file sequential read' ela= 33 file#=1 block#=3 blocks=8 obj#=-1 tim=1442286939777822
WAIT #139815001768920: nam='control file sequential read' ela= 16 file#=0 block#=1 blocks=1 obj#=-1 tim=1442286939777868
WAIT #139815001768920: nam='control file parallel write' ela= 1067 files=1 block#=1 requests=1 obj#=-1 tim=1442286939778965
WAIT #139815001768920: nam='control file sequential read' ela= 9 file#=1 block#=1 blocks=1 obj#=-1 tim=1442286939779062
WAIT #139815001768920: nam='control file parallel write' ela= 1021 files=1 block#=1 requests=1 obj#=-1 tim=1442286939780116
WAIT #139815001768920: nam='control file sequential read' ela= 12 file#=0 block#=16 blocks=1 obj#=-1 tim=1442286939780189
WAIT #139815001768920: nam='control file sequential read' ela= 7 file#=0 block#=18 blocks=1 obj#=-1 tim=1442286939780215
WAIT #139815001768920: nam='control file parallel write' ela= 2887 files=2 block#=17 requests=2 obj#=-1 tim=1442286939783204
WAIT #139815001768920: nam='control file parallel write' ela= 2805 files=2 block#=15 requests=2 obj#=-1 tim=1442286939786058
WAIT #139815001768920: nam='control file parallel write' ela= 15070 files=2 block#=1 requests=2 obj#=-1 tim=1442286939801190
WAIT #139815001768920: nam='control file sequential read' ela= 56 file#=0 block#=3 blocks=8 obj#=-1 tim=1442286939801347
WAIT #139815001768920: nam='control file parallel write' ela= 1004 files=1 block#=3 requests=1 obj#=-1 tim=1442286939802411
WAIT #139815001768920: nam='control file parallel write' ela= 1024 files=1 block#=4 requests=1 obj#=-1 tim=1442286939803521
一个一个的读取控制文件，并行的写入到控制文件中
针对上面的10046trace，做下面的解释:
file# 0---表示controlfile1
file # 1----表示controlfile2
block#---表示操作的block号
blocks---表示操作的block个数
files---表示操作的文件个数
从上面10046的trace结果，我们可以得到如下内容:
1.在数据库mount的时候，后台进程首先读取controlfile的第1个block,随后读取了controlfile的第3~11个block。
2.控制文件写入时，都是同时操作的。
最后我们根据前面的strace和10046跟踪来做一个简单地总结:
1)在数据库mount的时刻，数据库会通过读取controlfile来确认datafile以及redo等信息。这个读取操作是后台进程dbw0和lgwr来完成。
2)当数据库mount以后，ckpt进程会每3秒触发去更新controlfile
3)需要注意的是，相关后台进程在读取controlfile时，得知了datafile和redo等信息后，并不会去验证相关文件是否存在，在这个时候说明
数据库已经准备open了，不过在open的时刻，才会去验证相关文件是否存在。