DTrace即动态跟踪Dynamic Tracing

DTrace即动态跟踪Dynamic Tracing，是Solaris 10的一个新功能，透过此一新功能，用户能够动态检测操作系统内核和用户进程，以更精确地掌握系统的资源使用状况，提高系统性能，减少支持成本，并进行有效的调节。

已开始琢磨Dtrace,  既然有人喜欢，就分享下对Dtrace的印象

1997年，供职于Sun而现已是Solaris内核开发部高级工程师的Bryan Cantrill 与他的工作组在紧张地研究一个性能问题，它出现在刚刚提及的Sun E10000服务器。该服务器在运行基准测试时，速度突然在一段时间内奇怪地降低。工作组经过六天夜以继日的工作后，终于发现了问题的根本原因。某个“愚蠢之极”的配置错误将服务器配置成了路由器。

“我很受震惊，”Cantrill 说到， “这是任何一个客户都可能遇到的问题，但是他们可不敢奢望让内核开发人员为之夜以继日地工作，编写自定义代码以弄清楚问题。我们得找出一个更好的方法。”
经过两年半的紧张开发，Cantrill和他的工作组终于研究出了这个更好的方法： Dtrace

DTrace是过去十年中在操作系统方面最具意义的革新之一:

Probe，Solaris中分散着30,000多的位置指针，也叫探测器probes，DTrace可激活成千上万的探测器，记录所关注的位置指定的数据，如命中，即可从该地址显示用户进程或系统内核的数据，从而了解系统，包括：
1。任何函数的参数
2。内核的任何全局变量
3。函数调用的时间（NS，十亿分之一秒，无任何其它PC/Unix在ns一级精度）
4。跟踪堆栈，包括指明函数调用的代码
5。函数调用时运行的进程
6。产生函数调用的线程

Probe于自定义D语言程序相关联，probe表示的格式为：

provider:module:function:name

1。显示当前动态系统中的动态Dtrace探针probe:

# dtrace -l |more
  ID   PROVIDER            MODULE                          FUNCTION NAME
   1     dtrace                                                     BEGIN
   2     dtrace                                                     END
   3     dtrace                                                     ERROR
   4     vminfo          fasttrap                   fasttrap_uwrite softlock
   5     vminfo          fasttrap                    fasttrap_uread softlock
   6        fbt              pool                         pool_open entry
   7        fbt              pool                         pool_open return
   8        fbt              pool                        pool_close entry
   9        fbt              pool                        pool_close return
  10        fbt              pool                        pool_ioctl entry
  11        fbt              pool                        pool_ioctl return
  12        fbt              pool                         pool_info entry
  13        fbt              pool                         pool_info return
。。。
43545        fbt              zmod                        z_strerror return
43546        fbt              zmod                      z_uncompress entry
43547        fbt              zmod                      z_uncompress return


即当前本人V210上有43547个probe。


2。体验 dtrace 与 Unix ps 命令：

如用ps看mozilla进程：

# ps -e |grep mozilla
 2386 pts/11      0:00 mozilla
 2436 pts/11     10:12 mozilla-

也可使用dtrace 通过probe探针看：

# dtrace -n 'syscall::exece:return { trace(execname);}'
dtrace: description 'syscall::exece:return ' matched 1 probe
CPU     ID                    FUNCTION:NAME
 0  11082                     exece:return   uname                            
 0  11082                     exece:return   uname                            
 0  11082                     exece:return   basename  
。。。
 0  11082                     exece:return   sed                              
 0  11082                     exece:return   mozilla-bin                      
 1  11082                     exece:return   csh                              
 1  11082                     exece:return   mozilla      
。。。

2。实际dtrace看的更细，

如用date显示系统时间，很快就结束了，无法跟踪，体验dtrace跟踪效果：

% date
2005年05月24日 星期二 20时39分03秒 CST

# dtrace -n 'syscall::exece: '
ddtrace: description 'syscall::exece: ' matched 2 probes
CPU     ID                    FUNCTION:NAME
 0  11081                      exece:entry   102890531281542
 0  11082                     exece:return   102890532181875

即可跟踪其在第102890531281542纳秒开始读取，第102890532181875返回结果。


3。体验Dtrace 对系统调用更多的观察：

如看机器忙闲状态，常用vmstat:

# vmstat 1
kthr      memory            page            disk          faults      cpu
r b w   swap  free  re  mf pi po fr de sr s0 s3 s1 s1   in   sy   cs us sy id
0 0 0 5523680 1378352 14 48 84 1  0  0  1  0  1  0  0  341 2058  883  3  1 96
0 0 0 5368296 1218688 0 23 15  0  0  0  0  0  0  0  0  336 2605  722 10  1 89

得知产生2605多系统调用，但无和简单查找哪个进程的问题呢，试用dtrace看：

# dtrace -n 'syscall::read:entry {@NUM[execname] = count();}'
ddtrace: description 'syscall::read:entry ' matched 1 probe
^C

 dtfile                                                            5
 sdtperfmeter                                                     12
 soffice.bin                                                      23
 dic                                                              23
 dtterm                                                           53
 mozilla-bin                                                     394
 Xsun                                                            545

显然发现CDE和Mozilla是产生大量系统调用的程序，看I/O分布也可：

如还是Mozilla:

# dtrace -n 'syscall::write:entry {@NUM[execname] = quantize(arg2);}'
...

 mozilla-bin                                      
          value  ------------- Distribution ------------- count    
              0 |                                         0        
              1 |@@@@@@@@@@@@@@@@@@@@@                    470      
              2 |                                         0        
              4 |                                         7        
              8 |                                         0        
             16 |                                         0        
             32 |                                         0        
             64 |                                         0        
            128 |                                         10      
            256 |@@@@@@@@                                 184      
            512 |@@@@@@                                   146      
           1024 |@@@                                      78      
           2048 |                                         8        
           4096 |                                         1        
           8192 |                                         0    
...

可观察到大量Mozilla产生的I/O在256-512字节间。


4。 想再仔细看程序内部情况？

truss不错：

# truss /usr/sfw/bin/mozilla
execve("/usr/bin/ksh", 0xFFBFF564, 0xFFBFF574)  argc = 3
resolvepath("/usr/bin/ksh", "/usr/bin/ksh", 1023) = 12
resolvepath("/usr/lib/ld.so.1", "/lib/ld.so.1", 1023) = 12
stat("/usr/bin/ksh", 0xFFBFF340)                = 0
open("/var/ld/ld.config", O_RDONLY)             Err#2 ENOENT
stat("/lib/libc.so.1", 0xFFBFEE70)              = 0
resolvepath("/lib/libc.so.1", "/lib/libc.so.1", 1023) = 14
open("/lib/libc.so.1", O_RDONLY)                = 3
mmap(0x00010000, 8192, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_ALIGN, 3, 。。。


试下dtrace:

# dtrace -n 'syscall::read:return /execname =="mozilla" /{ ustack();}'
dtrace: description 'syscall::read:return ' matched 1 probe
CPU     ID                    FUNCTION:NAME
 0  10984                      read:return
             libc.so.1`_read+0x8
             ksh`io_readbuff+0x264
             ksh`0x245e4
             ksh`io_readc+0x2c
             ksh`0x29c54
             ksh`main+0xa30
             ksh`_start+0x108

 0  10984                      read:return
             libc.so.1`_read+0x8
             ksh`io_readbuff+0x264
             ksh`0x245e4
             ksh`io_readc+0x2c
             ksh`0x28938
             ksh`0x28654
...

看到n多调用，开始和返回，够开发人员分析的。

总结，Dtrace功能强大，精度高，轻量，truss有时降低系统30％CPU利用率。但复杂，需对系统内核和应用熟悉，否则看不懂跟踪到的数据，估计以后CU该开Dtrace编程板块了。