揭密Oracle之七种武器二：DTrace语法：跟踪物理IO
揭密Oracle之七种武器二：DTrace语法：跟踪物理IO
（章地址：
揭密Oracle之 七种武器 章 搭建测试环境
http://www.itpub.net/thread-1605241-1-1.html
或参考我的BLOG www.MythData.com
揭密Oracle之七种武器之三：破译古老的谜题---共享CBC Latch的秘密
http://www.itpub.net/thread-1617245-1-1.html
）
其实本章是以物理IO为例，介绍DTrace的基本语法。本篇内容还是比较多的，应该足够有兴趣的朋友学习一周了。下周，再推出我的第三章。:)
另外说明一下，我并不是DTrace专家，我用DTrace主要目的是研究Oracle。我们不会对DTrace作过多深入的介绍（不过DTrace本身也没有深入的东西，调试工具吗，复杂的是要调试的目标），我们的主要内容，还是逐步深入，介绍如何用DTrace分析、研究Oracle方法。
授人以鱼，不如授人以渔。我相信，方法比结果重要。
本篇内容会用到一本书，Solaris 动态跟踪指南，可以到这里下载。 这个是Solaris官方提供的文档，而且是中文的。当字典来查，非常不错。
1 781 bdev_strategy:start
1 781 bdev_strategy:start
1 781 bdev_strategy:start
1 781 bdev_strategy:start /export/home/oracle/opt/dbdata/h1/control01.ctl
1 781 bdev_strategy:start /export/home/oracle/opt/dbdata/h1/control01.ctl
1 781 bdev_strategy:start /export/home/oracle/opt/dbdata/h1/control01.ctl
可以看到，有很多控制文件的写。随带说一下，我这个测试库很闲，没有任何操作。但你可以看着表统计一下，不超过3秒，肯定会有一次控制文件的IO操作。原
因是什么，我就不用再说了吧。
再进一步的，Oracle每次控制文件的IO是多大呢？ IO的大小在bufinfo_t结构中的b_bcount域，你可以查看《Solaris 动态跟踪指南》 356页，为了节省篇幅，我
就不再粘过来了。bufinfo_t结构的指针，是bdev_strategy的个参数，也就是args[0]。因此，我们可以如下再次修改代码：
io:genunix:bdev_strategy:start
{
printf("%s %d",args[2]->fi_pathname,args[0]->b_bcount);
}
这是我的执行结果：
1 781 bdev_strategy:start /export/home/oracle/opt/dbdata/h1/control01.ctl 8192
2 781 bdev_strategy:start /var/tmp/Exwla4xc 8192
2 781 bdev_strategy:start /export/home/oracle/opt/dbdata/h1/redo03 4096
1 781 bdev_strategy:start /export/home/oracle/opt/dbdata/h1/control01.ctl 8192
1 781 bdev_strategy:start /export/home/oracle/opt/dbdata/h1/control01.ctl 8192
1 781 bdev_strategy:start /export/home/oracle/opt/dbdata/h1/control01.ctl 8192
控制文件的IO大小，很整齐的都是8192字节，8K，控制文件的块大小。出乎我意料的是，有一个Redo文件：redo03，它的IO大小是4096。我以前一直以为，应该是
512才对，因为Solaris下，Redo的块大小就是512字节啊（我碰到的系统，好像只有HP的不是512）。
不急，我们还没有搞清楚这些IO是读还是写呢，说不定是归档的读Redo IO呢。还是bufinfo_t结构，b_flags域，说明了IO类型。关于这个域，在操作系统内部定
义了几个标志（就是用#define 定义的），B_WRITE代表IO是写，B_READ代表是读，还有些其他的，自己到357页查吧。
我将代码修改如下，添加上去IO类别的判断：
io:genunix:bdev_strategy:start
{
printf("%s %d %s",args[2]->fi_pathname,args[0]->b_bcount,args[0]->b_flags&B_READ?"R":"W" );
}
args[0]->b_flags&B_READ?"R":"W"，这种使用形式，条件表达式，是我们以后常用的形式，因为DTrace中没有if、while等流程控制语句，所以条件表达式将是if
的常用替代者，但它必竟替代不了复杂的控制语句。
仍然是为了程序不太好的人，介绍一下这个条件表达式：“条件？值1？值2”，将条件为True，值1为整个条件表达式的值。否则，值2为整个条件表达式的值。
这是执行结果：
3 781 bdev_strategy:start /export/home/oracle/opt/dbdata/h1/control01.ctl 8192 W
3 781 bdev_strategy:start /export/home/oracle/opt/dbdata/h1/control01.ctl 8192 W
2 781 bdev_strategy:start /export/home/oracle/opt/dbdata/h1/redo01 4096 W
1 781 bdev_strategy:start /export/home/oracle/opt/dbdata/h1/control01.ctl 8192 W
1 781 bdev_strategy:start /export/home/oracle/opt/dbdata/h1/control01.ctl 8192 W
………………
控制文件IO也全是写，还有，中间的Redo文件IO，是我专门修改1行，Commit一下产生的，IO大小是4096字节，而且是写IO。看来，的确是LGWR在写Redo01。我们
可以观察一会儿，不会发现Redo文件有512字节IO，这也说明了一个我之前一直忽视的问题，先卖个关子，我们待会再讨论。
我们为io:genunix:bdev_strategy:start处的探针定义了动作，当运行此DTrace脚本时，我们就开启了探针io:genunix:bdev_strategy:start。但有些IO，并不是
通过bdev_strategy函数完成的，探针io:genunix:bdev_strategy:start捕获不得这些IO。为了开启更多的探针、捕获更多的IO操作，在完整的探针描述符中，我们可以确
实部分内容，下面，如下修改程序：
io:genunix::start
{
printf("%s %d %s",args[2]->fi_pathname,args[0]->b_bcount,args[0]->b_flags&B_READ?"R":"W" );
}
脚本程序运行后的提示：
# ./test2.d
dtrace: script './test2.d' matched 4 probes
CPU ID FUNCTION:NAME
2 782 bdev_strategy:start cmdk0 /export/home/oracle/opt/dbdata/h1/control01.ctl 8192 W
2 782 bdev_strategy:start cmdk0 /export/home/oracle/opt/dbdata/h1/control01.ctl 8192 W
2 782 bdev_strategy:start cmdk0 /export/home/oracle/opt/dbdata/h1/control01.ctl 8192 W
其中，行“dtrace: script './test2.d' matched 4 probes”，说明一共开启了4个探针，比之前的测试，多开启了两个探针。
我们还可以进一步省略，io:::start，这将开启7个探针。我就不再测试了。但我们不能写成:::start，或io:::这样的形式。
我们还可以使用通配符，如“i*:::start”，这就是打开所有i开头的提供器中的所有模块、所有函数的Start探针。当然，我们也可以在模块、函数名中，使用通
配符，但不能在探针名中使用通配符。比如，这样将是错误的：“io:::st*”。通配符还可以是问号，比如：“i?:::start”。 * 号代表所有字符，一个 ? 号，只能代表
一个字符。
探针的使用，说的也就差不多了，后再来一个总结，我们如何知道Solaris有哪些探针，当然，我们可以查看《Solaris 动态跟踪指南》。除了这个之外，
dtrace -l 命令可以查看所有的探针：
# dtrace -l|wc -l
51805
我使用的Solaris中，一共有5万多个探针。
我们还可以显示某一个提供器下所有探针，这样更有针对性，比如，显示io提供器下有什么模块、函数、探针：
# dtrace -lP io
ID PROVIDER MODULE FUNCTION NAME
767 io genunix biodone done
768 io genunix biowait wait-done
769 io genunix biowait wait-start
780 io genunix default_physio start
781 io genunix bdev_strategy start
782 io genunix aphysio start
2530 io nfs nfs4_bio done
2531 io nfs nfs3_bio done
2532 io nfs nfs_bio done
2533 io nfs nfs4_bio start
2534 io nfs nfs3_bio start
2535 io nfs nfs_bio start
不多，io提供器下，只有13个探针。
好了，探针的内容我们就说到这儿，下面，下一项内容：谓词。
[url=]/pci@0,0/pci-ide@7,1/ide@1/cmdk@1,0[/url]
1. c1t1d0
[url=]/pci@0,0/pci15ad,1976@10/sd@1,0[/url]
2. c1t3d0
[url=]/pci@0,0/pci15ad,1976@10/sd@3,0[/url]
3. c2t0d0
[url=]/pci@0,0/pci15ad,790@11/pci15ad,1976@3/sd@0,0[/url]
4. c2t1d0
[url=]/pci@0,0/pci15ad,790@11/pci15ad,1976@3/sd@1,0[/url]
Specify disk (enter its number):1 <-------------------------除了c0d1是我安装系统时，原始创建的磁盘外，剩下四个是后面添加的。此处我选择1号磁盘，
c1t1d0。
selecting c1t1d0
[disk formatted]
FORMAT MENU:
disk - select a disk
type - select (define) a disk type
partition - select (define) a partition table
current - describe the current disk
format - format and analyze the disk
fdisk - run the fdisk program
repair - repair a defective sector
label - write label to the disk
analyze - surface analysis
defect - defect list management
backup - search for backup labels
verify - read and display labels
save - save new disk/partition definitions
inquiry - show vendor, product and revision
volname - set 8-character volume name
! - execute , then return
quit
format> fdisk <------------------------应该先fdisk一下
No fdisk table exists. The default partition for the disk is:
a "SOLARIS System" partition
Type "y" to accept the default partition, otherwise type "n" to edit the
partition table.
y <-----------------------------此处输入y
format> partition <---------------------进入分区命令
PARTITION MENU:
0 - change `0' partition
1 - change `1' partition
2 - change `2' partition
3 - change `3' partition
4 - change `4' partition
5 - change `5' partition
6 - change `6' partition
7 - change `7' partition
select - select a predefined table
modify - modify a predefined partition table
name - name the current table
print - display the current table
label - write partition map and label to the disk
! - execute , then return
quit
partition> print <-------------------查看分区状态
Current partition table (original):
Total disk cylinders available: 98 + 2 (reserved cylinders)
Part Tag Flag Cylinders Size Blocks
0 unassigned wm 0 0 (0/0/0) 0
1 unassigned wm 0 0 (0/0/0) 0
2 backup wu 0 - 97 98.00MB (98/0/0) 200704 <-------2号分区已经被系统使用
3 unassigned wm 0 0 (0/0/0) 0
4 unassigned wm 0 0 (0/0/0) 0
5 unassigned wm 0 0 (0/0/0) 0
6 unassigned wm 0 0 (0/0/0) 0
7 unassigned wm 0 0 (0/0/0) 0
8 boot wu 0 - 0 1.00MB (1/0/0) 2048 <-------8号分区也已经被系统使用
9 unassigned wm 0 0 (0/0/0) 0
partition> 0 <--------------------------------------选择第0号分区，也可以选择1号、3号或其他的，但不能选择2号、8号这两个已经占用的。
Part Tag Flag Cylinders Size Blocks
0 unassigned wm 0 0 (0/0/0) 0
Enter partition id tag[unassigned]: <-------- 缺省，直接回车
Enter partition permission flags[wm]: <-------- 缺省，直接回车
Enter new starting cyl[0]:1 <-------- 如果要用ASM，此处要从1开始，否则可以从0开始
Enter partition size[0b, 0c, 0e, 0.00mb, 0.00gb]: 95mb <-------- 输入大小
partition> label <-------------设置label
Ready to label disk, continue? y <------------输入y
partition> quit <-------------退出partition，回到Format
FORMAT MENU:
disk - select a disk
type - select (define) a disk type
partition - select (define) a partition table
current - describe the current disk
format - format and analyze the disk
fdisk - run the fdisk program
repair - repair a defective sector
label - write label to the disk
analyze - surface analysis
defect - defect list management
backup - search for backup labels
verify - read and display labels
save - save new disk/partition definitions
inquiry - show vendor, product and revision
volname - set 8-character volume name
! - execute , then return
quit
format> type <----------------------------选择类型
AVAILABLE DRIVE *:
0. Auto configure
1. DEFAULT
2. other
Specify disk type (enter its number)[1]: 1 <---------------------此处选DEFAULT
selecting c1t1d0
[disk formatted]
format> save <-----------------------------此处，输入save，保存刚才做的所有工作
Saving new disk and partition definitions
Enter file name["./format.dat"]: <-----------------------此处直接回车
format> quit <---------------------退出
#
然后到刚才启动的ASM实例中，确定asm_diskstring参数的值为/dev/rdsk/c*：
SQL> show parameter string
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
asm_diskstring string /dev/rdsk/c*
查看我们刚才Format的磁盘：
SQL> select path from v$asm_disk;
PATH
--------------------------------------------------------------------------------
/dev/rdsk/c0d1s0
/dev/rdsk/c0d1s1
/dev/rdsk/c0d1s7
/dev/rdsk/c0d1s9
/dev/rdsk/c1t1d0s0
/dev/rdsk/c1t1d0s0，即为我们刚才Format的磁盘。c0d1s9这些不是，这些是装系统时建的盘。
说到这儿，补充一下Solaris下磁盘名的格式：
/dev/[r]dsk/cXtXdXsX
c:逻辑控制器号（逻辑控制器）
t:物理总线目标号
d:磁盘或逻辑单元号(LUN)
s:分区号
如c1t1d0s0表示1号控制器，1号磁盘，0号LUN，0号分区。
分完区后，不需要设置属主，ASM就可以自动识别到了。再把其他的盘也Format一下，让ASM可以识别到。
我终选择了这两块盘创建DG：
SQL> create diskgroup dg1 external redundancy disk '/dev/rdsk/c2t1d0s3','/dev/rdsk/c1t3d0s3';
Diskgroup created.
然后我们把Redo挪到ASM的dg1中，我在asmcmd中，在DG1里面建了一个redo目录，然后到数据库实例中，将组2、组3挪进了ASM。在删除组1、再添加组1到ASM中时
，报ASM空间不足。算了，我的磁盘太小了。
alter database drop logfile group 2;
alter database add logfile group 2 ('+DG1/redo/redo2.log') size 60m reuse;
alter database drop logfile group 3;
alter database add logfile group 3 ('+DG1/redo/redo3.log') size 60m reuse;
alter database drop logfile group 1;
现在我只有两组日志，都在ASM中，对于我们测试来说，两组已经够了：
SQL> select * from v$log;
GROUP# THREAD# SEQUENCE# BYTES MEMBERS ARC STATUS FIRST_CHANGE# FIRST_TIM
---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- ---------
2 1 489 62914560 1 NO CURRENT 9400623 07-MAY-12
3 1 0 62914560 1 YES UNUSED 0
好了，开始我们的测试吧。修改一下脚本：
io:::start
{
printf("%s %s %d %s\n",args[1]->dev_statname,args[2]->fi_pathname,args[0]->b_bcount,args[0]->b_flags&B_READ?"R":"W" );
}
将上面所加的args[2]->fi_pathname=="/export/home/oracle/opt/dbdata/h1/redo1.log" 这种谓词去掉。
# ./test2.d
dtrace: script './test2.d' matched 7 probes
CPU ID FUNCTION:NAME
1 3092 default_physio:start sd5 4096 W
1 3092 default_physio:start sd2 4096 W
3 3093 bdev_strategy:start cmdk0 /export/home/oracle/opt/dbdata/h1/control01.ctl 8192 W
3 3093 bdev_strategy:start cmdk0 /export/home/oracle/opt/dbdata/h1/control01.ctl 8192 W
……………………………………
……………………………………
……………………………………
由于打开了7个探针，所有IO开始时的操作都会被我们捕获，因此，输出信息会比较多。
在Oracle 会话中，修改一行数据，再提交，可以观察到这样的IO：
2 3094 aphysio:start sd3 [url=]/devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw[/url] 1024 W
[url=]/devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw[/url]，这一串东西是啥？只要显示一下ASM中的磁盘就明了了，我的ASM DG1 中包含这两块盘/dev/rdsk/c2t1d0s3，
/dev/rdsk/c1t3d0s3。
# ls -lFrt /dev/rdsk/c2t1d0s3
lrwxrwxrwx 1 root root 64 Mar 17 10:03 /dev/rdsk/c2t1d0s3 -> ../../devices/pci@0,0/pci15ad,790@11/pci15ad,1976@3/sd@1,0:d,raw*
# ls -lFrt /dev/rdsk/c1t3d0s3
lrwxrwxrwx 1 root root 50 Mar 17 10:03 /dev/rdsk/c1t3d0s3 -> ../../devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw
经过观察，可以发现，刚才的IO，其实是针对/dev/rdsk/c1t3d0s3的，这正是DG1中的一块盘。接下来我们如下修改脚本：
io:::start
/ args[2]->fi_pathname=="[url=]/devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw[/url]" ||
args[2]->fi_pathname=="[url=]/devices/pci@0,0/pci15ad,790@11/pci15ad,1976@3/sd@1,0:d,raw[/url]" /
{
printf("%s %s %d %s\n",args[1]->dev_statname,args[2]->fi_pathname,args[0]->b_bcount,args[0]->b_flags&B_READ?"R":"W" );
}
我们只观察针对这两个磁盘的IO。执行一条简单的DML，修改一行，我执行如下命令：
SQL> update a1 set id=id+0 where id=2;
1 row updated.
SQL> commit;
Commit complete.
在提交时，可以发现会有如下的IO：
3 783 aphysio:start sd5 [url=]/devices/pci@0,0/pci15ad,790@11/pci15ad,1976@3/sd@1,0:d,raw[/url] 1024 W
每次提交时，都会有IO发生，这是和文件系统的大区别。这样的话，我们提交的数据，就不会丢失了。有时，也可以观察到512字节的IO。
再进一步的，我们知道，在ASM中，AU的大小通常是1M，条带大小也为1M。但Redo和控制文件Oracle会将它们设置为“细粒度条带”，条带大小为128K。这个128K
，到底有什么意义呢？ 为什么我上面一定要在ASM DG1中，至少搞两块磁盘，就是为了观察这个“细粒度条带”。我们继续。
经过观察，我测试用的两条命令，update a1 set id=id+0 where id=2;，commit，每次执行，都会产生1K的Redo。这种说法也不太准备，更准确应该是这两条命
令，每次执行会触发Lgwr 执行1K的IO写操作。其实这两条语句产生的Redo只有700多字节，但提交的时候，LGWR写Redo数据，只能以块为单位去写。700多字节，正好占两
个日志块，1K字节。
脚本再做一下修改，完整的脚本如下：
#!/usr/sbin/dtrace -s
BEGIN
{
i=0;
}
io:::start
/ args[2]->fi_pathname=="[url=]/devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw[/url]" ||
args[2]->fi_pathname=="[url=]/devices/pci@0,0/pci15ad,790@11/pci15ad,1976@3/sd@1,0:d,raw[/url]" /
{
printf("IO number:%d %s %s %d %s\n",i,args[1]->dev_statname,args[2]->fi_pathname,args[0]->b_bcount,args[0]->b_flags&B_READ?"R":"W" );
i++;
}
我把之前用过的i++加了进来，主要用来观察IO的次数。好，运行这个程序，然后反反复复的执行上面的DML和提交语句。
# ./test2.d
dtrace: script './test2.d' matched 7 probes
CPU ID FUNCTION:NAME
3 783 aphysio:start IO number:0 sd5 [url=]/devices/pci@0,0/pci15ad,790@11/pci15ad,1976@3/sd@1,0:d,raw[/url] 1024 W
3 783 aphysio:start IO number:1 sd5 [url=]/devices/pci@0,0/pci15ad,790@11/pci15ad,1976@3/sd@1,0:d,raw[/url] 1024 W
…………………………………………省略部分内容…………………………………………
0 783 aphysio:start IO number:99 sd5 [url=]/devices/pci@0,0/pci15ad,790@11/pci15ad,1976@3/sd@1,0:d,raw[/url] 1024 W
2 783 aphysio:start IO number:100 sd3 [url=]/devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw[/url] 1024 W
2 783 aphysio:start IO number:101 sd3 [url=]/devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw[/url] 1024 W
…………………………………………省略部分内容…………………………………………
0 783 aphysio:start IO number:227 sd3 [url=]/devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw[/url] 1024 W
0 783 aphysio:start IO number:228 sd5 [url=]/devices/pci@0,0/pci15ad,790@11/pci15ad,1976@3/sd@1,0:d,raw[/url] 1024 W
0 783 aphysio:start IO number:229 sd5 [url=]/devices/pci@0,0/pci15ad,790@11/pci15ad,1976@3/sd@1,0:d,raw[/url] 1024 W
…………………………………………省略部分内容…………………………………………
0 783 aphysio:start IO number:354 sd5 [url=]/devices/pci@0,0/pci15ad,790@11/pci15ad,1976@3/sd@1,0:d,raw[/url] 1024 W
0 783 aphysio:start IO number:355 sd5 [url=]/devices/pci@0,0/pci15ad,790@11/pci15ad,1976@3/sd@1,0:d,raw[/url] 1024 W
0 783 aphysio:start IO number:356 sd3 [url=]/devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw[/url] 1024 W
0 783 aphysio:start IO number:357 sd3 [url=]/devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw[/url] 1024 W
^C
上面的结果，注意IO number:0的值，从IO number:100到IO number:227为止，共128次1K的IO，都是针对，磁盘设
备“/devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw”，从228次IO到355次IO，共128次1K IO，针对另一磁盘设
备“/devices/pci@0,0/pci15ad,790@11/pci15ad,1976@3/sd@1,0:d,raw”。
这就是细粒度条带的意义。虽然AU大小仍为1M，文件仍是按1M来分配空间。文件的个1M，在磁盘1，第二个1M，在磁盘2，等等。但在使用空间的时候，却是按
128K。先在磁盘1写128K，再在磁盘2中写128K，等等。
后，还有一个问题，比如第100和101次IO：
2 783 aphysio:start IO number:100 sd3 [url=]/devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw[/url] 1024 W
2 783 aphysio:start IO number:101 sd3 [url=]/devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw[/url] 1024 W
这是两次IO，每次IO的大小是1K，但是，我们如何确定这两次1K大小的IO，一共写了4个日志块？有没有可能100次IO，写了1、2号日志块，101次IO，写了2、3号
日志块，两次1K大小的IO，总共写了1.5K数据？
之所以有这样的疑问，是因为我的那条DML加提交，产生的Redo量是700多字节。虽然要占两个块，但是占不满两个块。那么，接下来的一次针对Redo的IO，是从没
占满的块继续往下写，还是新占一个块？
在资料视图中，有一个资料redo wastage，Redo浪费空间。如果两次IO每次各占两个块，redo wastage会不会有增加呢？ 我用如下语句查了一下
SQL> col name for a20
SQL> select name,value from v$sesstat a,v$statname b where a.statistic#=b.statistic# and b.name in( 'redo size','redo wastage') and sid=855;
NAME VALUE
-------------------- ----------
redo size 774092
redo wastage 0
855号会话，就是我反反复复执行那条DML、提交语句的会话。我们没有观察到这个会话中有Redo浪费。通过这个结果，我上面的测试，好像两次相邻的、1K大小的
IO，应该并没有产生共2K的Redo，应该只有1.5K。
但是，如果是这样的话，我们上面关于“细粒度条带”的结论，就有问题了。因为它是建立在连续128次1K大小的IO，共写了128K Redo基本上的。或者说，是建立
在两次相邻的、1K大小的IO，一定会产生2K的Redo这个基础上。但通过redo wastage分析的结果，好像应该只有1.5K才对。
到底结果如何，如果要确定的话，我们只能分析每次Redo IO的内容了。请看下节：“获取进程数据”
第二章 DTrace语法：跟踪物理IO
节 Hello World
DTrace是什么，这个问题很容易回答：调试工具。具体我们可以这样理解，Solaris在其内部，增加了N多的触发器，这些触发器平时是Disable的，对性能没有任 何影响。你可以通过DTrace，Enable某些触发器。并且，在Enable的同时，还可以为这些触发器指定动作。 比如，有一个I/O触发器，你用DTrace Enable了它，同时，你定义动作，“每次发生I/O时，显示出I/O大小”。当然，还可以定义更复杂的动作，显示I/O的内容 、甚至修改I/O数据。进程想往磁盘中写个A，你可以用DTrace，将A换成B。当然，我们调试进程，一般不需要修改，只需要观察。 换成DTrace中的术语，触发器就是Probe，可以译为探针。探针并时都是关闭的，也就是Disable的。我们可以使用DTrace，打开探针，并为探针指定动作。当探针 被触发，你通过DTrace为探针定义的动作，就会被执行。 好，闲言少叙，试试我们的个DTrace程序吧。曾几何时，无论我们学习什么语言，个程序总是“Hello World”，让我们也来个DTrace版的“Hello World ”吧。 在root下，vi test1.d，输入如下命令： BEGIN { printf("hello world,www.MythData.com "); exit(0); } 如下执行此脚本： # dtrace -s test1.d 结果显示： dtrace: script 'test1.d' matched 1 probe CPU ID FUNCTION:NAME 3 1 :BEGIN hello world,www.MythData.com 在此加上我的BLOG地址，我的那篇突然35岁，虽然被转载的到处都是，但被截掉了我的BLOG地址。唉。如果有人转载的话，应该也会有人截掉的。 闲言少叙，上面就是显示结果了。对于我的程序和输出结果，略加说明。 1、BEGIN：它是DTrace的探针之一。也是简单的探针。它不和操作系统任何操作关联，一般它用来做DTrace程序运行的初始化工作。BEGIN探针中的代码，会在 DTrace程序开始时运行。 2、大括号：如我们所见，探针名之下，就是大括号。这足以说明DTrace的设计者是C语言迷，将C语言的格式带入到了DTrace中来。 3、大括号中间的语句：这就是我们为BEGIN探针定义的动作了。包含两条语句，显示和退出。每条语句之后以;号结尾。 4、关于这两条语句，我就不再多说了，printf，在此的使用方法，完全和C语言一样。 5、两注意事项，（1）、大小写是敏感的。（2）、如果不加exit(0)的话，此程序运行完将不会退出。可以手工Ctrl+C退出。 输出结果的话： 1、CPU列为3，说明此DTrace程序在运行时，刚好在3号CPU上执行命令。 2、ID列是探针编号。 3、FUNCTION:NAME，:BEGIN，探针名相关信息，这个后面再详细说。 4、后无列名的部分，hello world,www.MythData.com，就是我们程序的输出结果了。 后，每次运行此程序时，都要dtrace -s，太麻繁了。我们可以添加一个#!/usr/sbin/dtrace -s在程序头，如下所示： #!/usr/sbin/dtrace -s BEGIN { printf("hello world,www.MythData.com "); exit(0); } 保存，使用chmod 755 test1.d，赋上去可执行权限，如下方式执行： # ./test1.d dtrace: script './test1.d' matched 1 probe CPU ID FUNCTION:NAME 0 1 :BEGIN hello world,www.MythData.com第二节 详述探针（Probe）
完整的探针描述符，不至上节我们遇到的BEGIN这么简单。它包括PROVIDER（提供器），MODULE（模块名），FUNCTION（函数名）和NAME（探针名称）四部分 。BEGIN只是简单的一个特例。 PROVIDER是上层的称号，比如有IO PROVIDER，进程PROVIDER，等等。每种PROVIDER根据其包含的探针不同，又分为N种MODULE。MODULE之中又包含各种FUNCTION ，后的NAME是探针名，通常是进入、开始、退出、完成这些东西，在进入一个FUNCTION（函数)、退出函数、完成函数等等动作发生时被触发。 我们以IO为例，这应该是我们关心的话题。操作系统中大部分IO事件的开始处，有这样一个探针： io:genunix:bdev_strategy:start io是PROVIDER，genunix是MODULE。bdev_strategy是FUNCTION，所有串行磁盘I/O事件将调用bdev_strategy函数完成。后一个，start，bdev_strategy函数入口 处的探针。 我们可以这样称呼它，io提供器下的genunix模块中的bdev_strategy函数上的start探针。我们可以理解为某数据库下某Schema中的某个表上的某某触发器。一个 探针的称呼其实无所谓。了解Solaris一供为我们提供了什么PROVIDER（提供器），这些提供器下都有什么MODULE（模块），这些模块中都有什么FUNCTION（函数），以及 这些函数上都有什么探针，这才是重要的。关于这点，我们可以参考《Solaris 动态跟踪指南》，这是本书像一本字典，详细介绍了所有的提供器、模块等等。 好，先以io:genunix:bdev_strategy:start为例子，测试一下吧： vi test2.d #!/usr/sbin/dtrace -s BEGIN { i=0; } io:genunix:bdev_strategy:start { printf("%d number physio IO",i); i++; } 保存，chmod 755 test2.d，这是执行的结果： # ./test2.d dtrace: script './test2.d' matched 2 probes CPU ID FUNCTION:NAME 1 781 bdev_strategy:start 0 number physio IO 1 781 bdev_strategy:start 1 number physio IO 1 781 bdev_strategy:start 2 number physio IO 1 781 bdev_strategy:start 3 number physio IO 1 781 bdev_strategy:start 4 number physio IO 1 781 bdev_strategy:start 5 number physio IO …………………… 每有一次IO，程序会都会显示一行，“ 1 781 bdev_strategy:star”，这一部分是固定输出，这一部分其实可以用一个参数关掉。参数我们以 后再说。后面“ 0 number physio IO”，是我们程序的输出结果。 如果我们不按Ctrl+C，程序会一直显示下去。每有一次串行IO发生，准确说是每调用一次bdev_strategy函数，探针被触发一次，就会显示一行。 只显示IO的次数，也没啥意义。其实我们可以显示更多的东西。但要对IO类探针进一步了解些。 bdev_strategy既然被叫作函数，是函数的话，当然有参数。它一共有3个参数，参数1是bufinfo_t型的结构，参数2是devinfo_t型结构，参数3是fileinfo_t型结 构。可以参见《Solaris 动态跟踪指南》 356页。 另外，结构，Struct，C语言的基本东西。不会的话，去看看潭浩强的C语言吧。二级C语言，我想我们都应该没啥问题吧。确定写DTrace脚本，连二级C都不需要， 只需要对C语言有基本的了解即可。 这三个结构当中，fileinfo_t包含的有I/O所针对的文件名，请允许我粘一段《Solaris 动态跟踪指南》 359页的内容，fileinfo_t结构的定义： typedef struct fileinfo { string fi_name; /* name (basename of fi_pathname) */ string fi_dirname; /* directory (dirname of fi_pathname) */ string fi_pathname; /* full pathname */ offset_t fi_offset; /* offset within file */ string fi_fs; /* filesystem */ string fi_mount; /* mount point of file system */ } fileinfo_t; 在此，照顾一下不会C语言的人，简单说明一下，如果我们要访问结构中的内容，格式是“结构名.域”，或者“结构指针->域”。在DTrace中，我们得到的一般都 是指针。 好，下面我们改一下脚本程序： io:genunix:bdev_strategy:start { printf("%s",args[2]->fi_pathname); } args[2]，是bdev_strategy函数的第三个参数，这是Dtrace中的固定用法。DTrace中还会有一些类似的固定用法，可以参考《Solaris 动态跟踪指南》P68页，内 置变量。我们以后还会用到一些其他的。 在bdev_strategy函数中，第三个参数是fileinfo_t型的指针，也就是说，我们可以用“args[2]->域”的格式，访问fileinfo_t型结构中的域。我们此外访问的域 是fi_pathname，也就是文件的完整路径加名字，形式就是如上面所示：args[2]->fi_pathname。 这是我执行后的结果： # ./test2.d dtrace: script './test2.d' matched 2 probes CPU ID FUNCTION:NAME 2 781 bdev_strategy:start /export/home/oracle/opt/dbdata/h1/control01.ctl 2 781 bdev_strategy:start /export/home/oracle/opt/dbdata/h1/control01.ctl 0 781 bdev_strategy:start /export/home/oracle/opt/dbdata/h1/control01.ctl 0 781 bdev_strategy:start /export/home/oracle/opt/dbdata/h1/control01.ctl 1 781 bdev_strategy:start第三节 谓词
谓词其实就是条件语句，减化版的条件语句。比如，我们继续前面的例子，我只想观察一下针对Redo文件的IO，我们可以这样做，先用如下命令确认一下当前Redo 文件是谁： set linesize 10000 select * from v$log; GROUP# THREAD# SEQUENCE# BYTES MEMBERS ARC STATUS FIRST_CHANGE# FIRST_TIM ---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- --------- 1 1 470 62914560 1 YES ACTIVE 9387236 05-MAY-12 2 1 471 62914560 1 NO CURRENT 9388037 05-MAY-12 3 1 469 62914560 1 YES INACTIVE 9386469 05-MAY-12 2号Redo文件是当前Redo文件，再如下确认一下2号Redo文件是谁： select member from v$logfile where group#=2; MEMBER ------------------------------------------------------------------------------------------------------------------------------------------------------ /export/home/oracle/opt/dbdata/h1/redo2.log 好，如下修改脚本： io:::start / args[2]->fi_pathname=="/export/home/oracle/opt/dbdata/h1/redo2.log" / { printf("%s %s %d %s\n",args[1]->dev_statname,args[2]->fi_pathname,args[0]->b_bcount,args[0]->b_flags&B_READ?"R":"W" ); } 探针描述符我简写为：io:::start，我开启了所有IO开始处的探针，拦截io提供器下所有的IO函数调用。在探针描述符之下的 / ………… / ，就是本节所要介绍 的谓词。简单点说，就是条件。当探针被触发后，只有满足谓词条件，才会执行探针下的动作。 结合上面的程序，也就是当有IO发生时，只有当IO是针对redo2.log这个文件的，才会执行下面的Printf命令。 开一个数据库会话，使用update命令更新一行，观察一下行针对Redo的IO。 我针对一个很小的表，执行如下命令： SQL> update a1 set id=id+0 where id=1; 1 row updated. SQL> commit; Commit complete. 观察结果， update a1 set id=id+0 where id=1时，并没有Redo的IO，这是因为在全新的IMU模式下，Redo机制Oracle做了很大调整，DML语句执行时，只要没有 超过private strand大小，日志不会被写进Log Buffer。关于这些内容，后面我们专门开个帖子详细讨论吧。在Commit时，就有了如下输出： # ./test2.d dtrace: script './test2.d' matched 7 probes CPU ID FUNCTION:NAME 2 782 bdev_strategy:start cmdk0 /export/home/oracle/opt/dbdata/h1/redo2.log 4096 W 有4096字节的针对Redo2.log的写IO。但是，注意，并不是每次提交时，都会有IO。下面是我做的一个完整测试，我一共执行了上面的Update、commit命令共10次 ，有6次commit时有IO： # ./test2.d dtrace: script './test2.d' matched 7 probes CPU ID FUNCTION:NAME 2 782 bdev_strategy:start cmdk0 /export/home/oracle/opt/dbdata/h1/redo3.log 4096 W 2 782 bdev_strategy:start cmdk0 /export/home/oracle/opt/dbdata/h1/redo3.log 4096 W 3 782 bdev_strategy:start cmdk0 /export/home/oracle/opt/dbdata/h1/redo3.log 4096 W 1 782 bdev_strategy:start cmdk0 /export/home/oracle/opt/dbdata/h1/redo3.log 4096 W 3 782 bdev_strategy:start cmdk0 /export/home/oracle/opt/dbdata/h1/redo3.log 4096 W 2 782 bdev_strategy:start cmdk0 /export/home/oracle/opt/dbdata/h1/redo3.log 4096 W 我们可以用truss 跟踪一下lgwr进程，每次提交时，lgwr都会调用pwrite64函数，写Redo文件。写的大小不等，小时会是512字节。而且，每次提交时，都会写 Redo文件。这就是Oracle的运行法则之一吗，提交时，一定会写Redo文件。但是，如果你使用的是文件系统，对日志文件的写，操作系统有可能只是暂时先写进主机的缓存 当中。 当然，在Solaris下，我们可以mount -o directio 这样Mount磁盘，所有IO都将是直接IO了。 使用文件系统是危险的。我只了解Oracle，不了解各种文件系统。严谨点的说法，使用某些文件系统存放Redo文件是危险的。有可能造成提交后的数据丢失。如果 你决定使用文件系统，一定要详细了解下你的文件系统，针对Redo文件，是否是直接IO，或者在突然当机后的处理，有没有类似Oracle的实例恢复机制。 我们可以测试一下，做一个DML操作，提交，然后马上关掉主机电源（我是Power Off掉虚拟机的电源），再重新启动虚拟机、数据库，查看刚才已经提交DML的结 果，你会发现，有时DML的结果会丢失掉的。注意，是已提交的DML结果会丢失。 在谓词中，我们可以使用常见的||、&&、！，就是或、与、非。比如，我共有三个日志文件，上面的谓词我捕获一个日志文件redo2.log的IO，为了三个文件都捕 获，可以如下改写： io:::start / args[2]->fi_pathname=="/export/home/oracle/opt/dbdata/h1/redo1.log" || args[2]->fi_pathname=="/export/home/oracle/opt/dbdata/h1/redo2.log" || args[2]->fi_pathname=="/export/home/oracle/opt/dbdata/h1/redo3.log" / { printf("%s %s %d %s\n",args[1]->dev_statname,args[2]->fi_pathname,args[0]->b_bcount,args[0]->b_flags&B_READ?"R":"W" ); } 谓词中我使用两个||符号，也就是“或”，将三个条件连接起来。只要有任意一个条件满足，都会执行下面的printf命令。这样，无论日志怎么切换，我们都可以 观察Redo的IO情况了。 那么，ASM会不会有这样的情况呢，我们可以测试下。 首先，配置ASM。我们先在10G下测试吧，10G的ASM配置比较简单，网上资料也比较多。11GR2的，我们以后再配置、观察。 (1)、配置ASM # export ORACLE_HOME=/export/home/oracle/opt//product/10.2.0/ # cd $ORACLE_HOME/bin # ./localconfig add （2）、准备ASM参数文件 $ cat asmpfile.ora instance_type=asm cluster_database=false asm_diskgroups=dg1 asm_diskstring='/dev/rdsk/c*' processes=200 remote_login_passwordfile=exclusive core_dump_dest=/export/home/oracle/opt/admin/myasm/cdump user_dump_dest=/export/home/oracle/opt/admin/myasm/udump background_dump_dest=/export/home/oracle/opt/admin/myasm/bdump （3）、启动ASM实例 先要保证参数文件中background_dump_dest几个参数中所指定的位置是有的，如下启动ASM实例即可： ORACLE_SID=myasm sqlplus / as sysdba create spfile from pfile='/export/home/oracle/asmpfile.ora'; startup nomount; 在我博客上有一篇文章，专门讲如何配置ASM的：http://space.itpub.net/321157/viewspace-718805 （4）、给虚拟机添加新的磁盘。 这个我就不多说了，要先关掉虚拟机，添加完磁盘再重启。先添加两块吧，大小不用太大。 （5）、格式化 格式化的步骤比较长，我写的详细些： # format <----------------------------------format ，格式化命令。 Searching for disks...done AVAILABLE DISK SELECTIONS: 0. c0d1第四节 获取进程数据
不久前才看过一个笑话，从哪儿来的我也忘了。说是一名生物学家研究螃蠏的听觉系统，对着螃蠏大吼一声，螃蠏马上跑了。将螃蠏的腿截掉，对着螃蠏再次大吼 一声，螃蠏没有跑。因此证明螃蠏的听觉系统是在腿上。 我们做测试，千万不要无意中成为这名生物学家。用不严谨的测试、得到错误的结论，然后再用这个结论去分析碰到的问题，可想而知，这会是什么结果。 好，言归正传，继续上节中的测试，为了得到准确的结论，我们需要获得IO的内容。 继续做这个分析，需要我们对Redo的块格式，有简单的了解。 512字节的一个Redo块，前16字节，是块头。块头中第8到11字节，是块所属于日志序列号，第4到7字节，是块编号。接下来要做的，在Start探针中，读出块头， 将每次IO的日志序列号、块号显示出来。 DTrace中，可以使用copyin，《Solaris 动态跟踪指南》P155页，有这个函数的介绍。P411页，还有更详细的介绍。 简单点说，某个进程的数据，我们不能直接显示，要使用copyin拷贝到DTrace的缓存中，才能显示。如下修改我们的脚本： #!/usr/sbin/dtrace -s char *rd; char bn[4]; char seq[4]; BEGIN { i=0; } io:::start / args[2]->fi_pathname=="[url=]/devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw[/url]" || args[2]->fi_pathname=="[url=]/devices/pci@0,0/pci15ad,790@11/pci15ad,1976@3/sd@1,0:d,raw[/url]" / { rd=copyin((uintptr_t )(args[0]->b_addr),16); bn[0]=rd[4]; bn[1]=rd[5]; bn[2]=rd[6]; bn[3]=rd[7]; seq[0]=rd[8]; seq[1]=rd[9]; seq[2]=rd[10]; seq[3]=rd[11]; printf("IO number:%d %s %s %d %s Seq:%d,Block:%d\n",i,args[1]->dev_statname,args[2]->fi_pathname,args[0]->b_bcount,args[0]- >b_flags&B_READ?"R":"W",*((int *)&seq[0]),*((int *)&bn[0])); i++; } 解释一下这段脚本，首先，在开头的三个变量定义： char *rd; char bn[4]; char seq[4]; 我们在BEGIN探针中，也用过变量:i。在io:::start探针中，还对i做了自增操作。这三个变量与i的区别有两点，一它们是全局变量，二它们有类型。 只有这样的全局变量，才需要专门在程序开头定义，也只有它们，才可以有类型。可以使用的类型，同C语言一样。变量i我们没有定义，直接就开始使用。DTrace 根据它的值来决定它的类型。 然后，这行是这个脚本程序的关键： rd=copyin((uintptr_t )(args[0]->b_addr),16); (uintptr_t )(args[0]->b_addr)，这是我们的地址，我们从这个地址中，考贝16个字节，到rd中。rd是一个字符型指针，它的空间在DTrace缓存中。args[0]- >b_addr这个域的值，就是存放IO内容的缓存区地址。我们在这个地址前加一个(uintptr_t )，强制类型转换。因为在《Solaris 动态跟踪指南》P155页，我们可以看到： void *copyin(uintptr_t addr, size_t size) copyin要求的地址类型是uintptr_t型。但(args[0]->b_addr)的类型并不是这个，因此，我们需要加个强制类型转换。将(args[0]->b_addr)转成uintptr_t型。 在这里我拷贝了16个字节，就是整个块头了。下面的赋值语句： bn[0]=rd[4]; bn[1]=rd[5]; bn[2]=rd[6]; bn[3]=rd[7]; seq[0]=rd[8]; seq[1]=rd[9]; seq[2]=rd[10]; seq[3]=rd[11]; 将块头中的4到7字节，传到bn中，这是块号。将8到11字节，传到seq中，这是日志序列号。后一步输出时，是这样操作bn和seq这两个数组的： …………，*((int *)&seq[0]),*((int *)&bn[0]); &seq[0]，取出seq数组中0号元素的地址。(int *)，将这个地址转成整型，(int *)&seq[0]，是一个整型的地址，指向seq的开头。在它之前再加一个*，取出这个 整型地址中值。其实根本含意就是，将bn数组中的4个字节，当作一个整型变量输出。这是C语言中指针的常见玩法。在使用copyin时，可能会用的比较多。 好了，运行脚本，执行DML+提交，观察输出结果： …………………… 3 783 aphysio:start IO number:93 sd3 [url=]/devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw[/url] 1024 W Seq:495,Block:513 3 783 aphysio:start IO number:94 sd3 [url=]/devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw[/url] 1024 W Seq:495,Block:515 3 783 aphysio:start IO number:95 sd3 [url=]/devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw[/url] 1024 W Seq:495,Block:517 3 783 aphysio:start IO number:96 sd3 [url=]/devices/pci@0,0/pci15ad,1976@10/sd@3,0:d,raw[/url] 1024 W Seq:495,Block:519 …………………… 可以看到第93次IO写的是495号日志第513号块，大小1K。94次IO是495号日志515号块，大小1K，等等。 也就是说，两次相邻Commit触发的IO，各自写各自的块。两次1K的IO，共写了4个块。 也就是说，我们对“细粒度条带”的分析是不错的。但redo wastage资料中的值就有问题了，不知道它衡量的是什么浪费。我每次只产生700多字节Redo，用了 1024字节空间，但redo wastage的值为0。 好了，我们的揭密Oracle之七种武器之二，先到这里吧。第三章将继续介绍DTrace语法，同时结合Oracle的观察结果。 用一句广告语：精彩继续，敬请期待。相关文章